Reduce start domain unnecessary domain redefines (#1178)

Various checks in the start domain action were accidentally causing a
redefine right after initial create. Update to provide debug output when
the domain needs to be changed to allow capture of the redefines
occurring in the future and to make it easy for the tests to pick up
where the redefine was triggered by setting an expectation on the log
output.

Include a small fix to avoid running strip on what might be a nil object
returned for elements without any text attributes.

Fix a bug where changes to tpm settings made to the config after an
initial domain creation where there was previously no tpm defined, would
be ignored.

Adds a logger double and updates other tests that trigger log calls.

should fix #1176

lib/vagrant-libvirt/action/start_domain.rb

@@ -43,6 +43,7 @@ module VagrantPlugins
                 bus = disk[:bus]
                 REXML::XPath.each(xml_descr, '/domain/devices/disk[@device="disk"]/target[@dev="' + device + '"]') do |disk_target|
                   next unless disk_target.attributes['bus'] != bus
+                  @logger.debug "disk #{device} bus updated from '#{disk_target.attributes['bus']}' to '#{bus}'"
                   descr_changed = true
                   disk_target.attributes['bus'] = bus
                   disk_target.parent.delete_element("#{disk_target.parent.xpath}/address")
@@ -52,6 +53,7 @@ module VagrantPlugins
               # disk_bus
               REXML::XPath.each(xml_descr, '/domain/devices/disk[@device="disk"]/target[@dev="vda"]') do |disk_target|
                 next unless disk_target.attributes['bus'] != config.disk_bus
+                @logger.debug "domain disk bus updated from '#{disk_target.attributes['bus']}' to '#{bus}'"
                 descr_changed = true
                 disk_target.attributes['bus'] = config.disk_bus
                 disk_target.parent.delete_element("#{disk_target.parent.xpath}/address")
@@ -61,6 +63,7 @@ module VagrantPlugins
               unless config.nic_model_type.nil?
                 REXML::XPath.each(xml_descr, '/domain/devices/interface/model') do |iface_model|
                   if iface_model.attributes['type'] != config.nic_model_type
+                    @logger.debug "network type updated from '#{iface_model.attributes['type']}' to '#{config.nic_model_type}'"
                     descr_changed = true
                     iface_model.attributes['type'] = config.nic_model_type
                   end
@@ -68,7 +71,9 @@ module VagrantPlugins
               end
 
               # vCpu count
-              if config.cpus.to_i != libvirt_domain.num_vcpus(0)
+              vcpus_count = libvirt_domain.num_vcpus(0)
+              if config.cpus.to_i != vcpus_count
+                @logger.debug "cpu count updated from '#{vcpus_count}' to '#{config.cpus}'"
                 descr_changed = true
                 REXML::XPath.first(xml_descr, '/domain/vcpu').text = config.cpus
               end
@@ -76,11 +81,13 @@ module VagrantPlugins
               # cpu_mode
               cpu = REXML::XPath.first(xml_descr, '/domain/cpu')
               if cpu.nil?
+                @logger.debug "cpu_mode updated from not set to '#{config.cpu_mode}'"
                 descr_changed = true
                 cpu = REXML::Element.new('cpu', REXML::XPath.first(xml_descr, '/domain'))
                 cpu.attributes['mode'] = config.cpu_mode
               else
                 if cpu.attributes['mode'] != config.cpu_mode
+                  @logger.debug "cpu_mode updated from '#{cpu.attributes['mode']}' to '#{config.cpu_mode}'"
                   descr_changed = true
                   cpu.attributes['mode'] = config.cpu_mode
                 end
@@ -89,16 +96,19 @@ module VagrantPlugins
               if config.cpu_mode != 'host-passthrough'
                 cpu_model = REXML::XPath.first(xml_descr, '/domain/cpu/model')
                 if cpu_model.nil?
+                  @logger.debug "cpu_model updated from not set to '#{config.cpu_model}'"
                   descr_changed = true
                   cpu_model = REXML::Element.new('model', REXML::XPath.first(xml_descr, '/domain/cpu'))
                   cpu_model.attributes['fallback'] = 'allow'
                   cpu_model.text = config.cpu_model
                 else
-                  if cpu_model.text.strip != config.cpu_model.strip
+                  if (cpu_model.text or '').strip != config.cpu_model.strip
+                    @logger.debug "cpu_model text updated from #{cpu_model.text} to '#{config.cpu_model}'"
                     descr_changed = true
                     cpu_model.text = config.cpu_model
                   end
                   if cpu_model.attributes['fallback'] != config.cpu_fallback
+                    @logger.debug "cpu_model fallback attribute updated from #{cpu_model.attributes['fallback']} to '#{config.cpu_fallback}'"
                     descr_changed = true
                     cpu_model.attributes['fallback'] = config.cpu_fallback
                   end
@@ -107,12 +117,14 @@ module VagrantPlugins
                 svm_feature = REXML::XPath.first(xml_descr, '/domain/cpu/feature[@name="svm"]')
                 if config.nested
                   if vmx_feature.nil?
+                    @logger.debug "nested mode enabled from unset by setting cpu vmx feature"
                     descr_changed = true
                     vmx_feature = REXML::Element.new('feature', REXML::XPath.first(xml_descr, '/domain/cpu'))
                     vmx_feature.attributes['policy'] = 'optional'
                     vmx_feature.attributes['name'] = 'vmx'
                   end
                   if svm_feature.nil?
+                    @logger.debug "nested mode enabled from unset by setting cpu svm feature"
                     descr_changed = true
                     svm_feature = REXML::Element.new('feature', REXML::XPath.first(xml_descr, '/domain/cpu'))
                     svm_feature.attributes['policy'] = 'optional'
@@ -120,16 +132,19 @@ module VagrantPlugins
                   end
                 else
                   unless vmx_feature.nil?
+                    @logger.debug "nested mode disabled for cpu by removing vmx feature"
                     descr_changed = true
                     cpu.delete_element(vmx_feature)
                   end
                   unless svm_feature.nil?
+                    @logger.debug "nested mode disabled for cpu by removing svm feature"
                     descr_changed = true
                     cpu.delete_element(svm_feature)
                   end
                 end
               elsif config.numa_nodes == nil
                 unless cpu.elements.to_a.empty?
+                  @logger.debug "switching cpu_mode to host-passthrough and removing emulated cpu features"
                   descr_changed = true
                   cpu.elements.each do |elem|
                     cpu.delete_element(elem)
@@ -183,8 +198,9 @@ module VagrantPlugins
 
                 tpm = REXML::XPath.first(xml_descr, '/domain/devices/tpm')
                 if tpm.nil?
+                  @logger.debug "tpm created from previously not defined"
                   descr_changed = true
-                  tpm = REXML::Element.new('tpm', REXML::XPath.first(xml_descr, '/domain/devices/tpm/model'))
+                  tpm = REXML::Element.new('tpm', REXML::XPath.first(xml_descr, '/domain/devices'))
                   tpm.attributes['model'] = config.tpm_model
                   tpm_backend_type = tpm.add_element('backend')
                   tpm_backend_type.attributes['type'] = config.tpm_type
@@ -192,16 +208,20 @@ module VagrantPlugins
                   tpm_device_path.attributes['path'] = config.tpm_path
                 else
                   if tpm.attributes['model'] != config.tpm_model
+                    @logger.debug "tpm model updated from '#{tpm.attributes['model']}' to '#{config.tpm_model}'"
                     descr_changed = true
                     tpm.attributes['model'] = config.tpm_model
                   end
-                  if tpm.elements['backend'].attributes['type'] != config.tpm_type
+                  backend = tpm.elements['backend']
+                  if backend.attributes['type'] != config.tpm_type
+                    @logger.debug "tpm type updated from '#{backend.attributes['type']}' to '#{config.tpm_type}'"
                     descr_changed = true
-                    tpm.elements['backend'].attributes['type'] = config.tpm_type
+                    backend.attributes['type'] = config.tpm_type
                   end
-                  if tpm.elements['backend'].elements['device'].attributes['path'] != config.tpm_path
+                  if backend.elements['device'].attributes['path'] != config.tpm_path
+                    @logger.debug "tpm path updated from '#{backend.elements['device'].attributes['path']}' to '#{config.tpm_path}'"
                     descr_changed = true
-                    tpm.elements['backend'].elements['device'].attributes['path'] = config.tpm_path
+                    backend.elements['device'].attributes['path'] = config.tpm_path
                   end
                 end
               end
@@ -210,16 +230,21 @@ module VagrantPlugins
               video = REXML::XPath.first(xml_descr, '/domain/devices/video')
               if !video.nil? && (config.graphics_type == 'none')
                 # graphics_type = none, video devices are removed since there is no possible output
+                @logger.debug "deleting video elements as config.graphics_type is none"
                 descr_changed = true
                 video.parent.delete_element(video)
               else
                 video_model = REXML::XPath.first(xml_descr, '/domain/devices/video/model')
                 if video_model.nil?
+                  @logger.debug "video updated from not set to type '#{config.video_type}' and vram '#{config.video_vram}'"
+                  descr_changed = true
                   video_model = REXML::Element.new('model', REXML::XPath.first(xml_descr, '/domain/devices/video'))
                   video_model.attributes['type'] = config.video_type
                   video_model.attributes['vram'] = config.video_vram
                 else
-                  if video_model.attributes['type'] != config.video_type || video_model.attributes['vram'] != config.video_vram
+                  if video_model.attributes['type'] != config.video_type || video_model.attributes['vram'] != config.video_vram.to_s
+                    @logger.debug "video type updated from '#{video_model.attributes['type']}' to '#{config.video_type}'"
+                    @logger.debug "video vram updated from '#{video_model.attributes['vram']}' to '#{config.video_vram}'"
                     descr_changed = true
                     video_model.attributes['type'] = config.video_type
                     video_model.attributes['vram'] = config.video_vram
@@ -237,11 +262,13 @@ module VagrantPlugins
               if config.dtb
                 dtb = REXML::XPath.first(xml_descr, '/domain/os/dtb')
                 if dtb.nil?
+                  @logger.debug "dtb updated from not set to '#{config.dtb}'"
                   descr_changed = true
                   dtb = REXML::Element.new('dtb', REXML::XPath.first(xml_descr, '/domain/os'))
                   dtb.text = config.dtb
                 else
-                  if dtb.text != config.dtb
+                  if (dtb.text or '') != config.dtb
+                    @logger.debug "dtb updated from '#{dtb.text}' to '#{config.dtb}'"
                     descr_changed = true
                     dtb.text = config.dtb
                   end
@@ -252,11 +279,13 @@ module VagrantPlugins
               if config.kernel
                 kernel = REXML::XPath.first(xml_descr, '/domain/os/kernel')
                 if kernel.nil?
+                  @logger.debug "kernel updated from not set to '#{config.kernel}'"
                   descr_changed = true
                   kernel = REXML::Element.new('kernel', REXML::XPath.first(xml_descr, '/domain/os'))
                   kernel.text = config.kernel
                 else
-                  if kernel.text != config.kernel
+                  if (kernel.text or '').strip != config.kernel
+                    @logger.debug "kernel updated from '#{kernel.text}' to '#{config.kernel}'"
                     descr_changed = true
                     kernel.text = config.kernel
                   end
@@ -265,11 +294,13 @@ module VagrantPlugins
               if config.initrd
                 initrd = REXML::XPath.first(xml_descr, '/domain/os/initrd')
                 if initrd.nil?
+                  @logger.debug "initrd updated from not set to '#{config.initrd}'"
                   descr_changed = true
                   initrd = REXML::Element.new('initrd', REXML::XPath.first(xml_descr, '/domain/os'))
                   initrd.text = config.initrd
                 else
-                  if initrd.text != config.initrd
+                  if (initrd.text or '').strip != config.initrd
+                    @logger.debug "initrd updated from '#{initrd.text}' to '#{config.initrd}'"
                     descr_changed = true
                     initrd.text = config.initrd
                   end

spec/support/libvirt_context.rb

@@ -7,6 +7,7 @@ shared_context 'libvirt' do
   let(:id)              { 'dummy-vagrant_dummy'     }
   let(:connection)      { double('connection') }
   let(:domain)          { double('domain') }
+  let(:logger)          { double('logger') }
 
   def connection_result(options = {})
     result = options.fetch(:result, nil)
@@ -26,5 +27,6 @@ shared_context 'libvirt' do
     allow(domain).to receive(:mac).and_return('9C:D5:53:F1:5A:E7')
 
     allow(machine).to receive(:id).and_return(id)
+    allow(Log4r::Logger).to receive(:new).and_return(logger)
   end
 end

spec/support/sharedcontext.rb

@@ -3,10 +3,14 @@ require 'spec_helper'
 shared_context 'unit' do
   include_context 'vagrant-unit'
 
+  let(:vagrantfile_providerconfig) { '' }
   let(:vagrantfile) do
     <<-EOF
     Vagrant.configure('2') do |config|
       config.vm.define :test
+      config.vm.provider :libvirt do |libvirt|
+        #{vagrantfile_providerconfig}
+      end
     end
     EOF
   end

spec/unit/action/create_domain_spec.rb

@@ -26,6 +26,7 @@ describe VagrantPlugins::ProviderLibvirt::Action::CreateDomain do
 
       allow(connection).to receive(:servers).and_return(servers)
       allow(connection).to receive(:volumes).and_return(volumes)
+      allow(logger).to receive(:info)
     end
 
     context 'default pool' do

spec/unit/action/start_domain_spec.rb

@@ -16,6 +16,7 @@ describe VagrantPlugins::ProviderLibvirt::Action::StartDomain do
   let(:servers) { double('servers') }
 
   let(:domain_xml) { File.read(File.join(File.dirname(__FILE__), File.basename(__FILE__, '.rb'), test_file)) }
+  let(:updated_domain_xml) { File.read(File.join(File.dirname(__FILE__), File.basename(__FILE__, '.rb'), updated_test_file)) }
 
   describe '#call' do
     before do
@@ -26,6 +27,7 @@ describe VagrantPlugins::ProviderLibvirt::Action::StartDomain do
 
       allow(connection).to receive(:servers).and_return(servers)
       allow(servers).to receive(:get).and_return(domain)
+      expect(logger).to receive(:info)
     end
 
     context 'default config' do
@@ -38,12 +40,35 @@ describe VagrantPlugins::ProviderLibvirt::Action::StartDomain do
         allow(libvirt_domain).to receive(:num_vcpus).and_return(1)
       end
 
-      it 'should execute correctly' do
+      it 'should execute without changing' do
+        allow(libvirt_domain).to receive(:undefine)
+        expect(logger).to_not receive(:debug)
         expect(libvirt_domain).to receive(:autostart=)
         expect(domain).to receive(:start)
 
         expect(subject.call(env)).to be_nil
       end
+
+      context 'tpm_path added' do
+        let(:updated_test_file) { 'default_added_tpm_path.xml' }
+        let(:vagrantfile_providerconfig) do
+          <<-EOF
+          libvirt.tpm_path = '/dev/tpm0'
+          libvirt.tpm_type = 'passthrough'
+          libvirt.tpm_model = 'tpm-tis'
+          EOF
+        end
+
+        it 'should modify the domain tpm_path' do
+          expect(libvirt_domain).to receive(:undefine)
+          expect(logger).to receive(:debug).with('tpm created from previously not defined')
+          expect(servers).to receive(:create).with(xml: updated_domain_xml)
+          expect(libvirt_domain).to receive(:autostart=)
+          expect(domain).to receive(:start)
+
+          expect(subject.call(env)).to be_nil
+        end
+      end
     end
   end
 end

spec/unit/action/start_domain_spec/default.xml

@@ -8,14 +8,14 @@
 
 
   <cpu mode='host-model'>
-      <model fallback='allow'></model>
+      <model fallback='allow'/>
   </cpu>
 
 
   <os>
         <type>hvm</type>
     <kernel/>
-    <initrd></initrd>
+    <initrd/>
     <cmdline/>
   </os>
   <features>

spec/unit/action/start_domain_spec/default_added_tpm_path.xml

@@ -0,0 +1,48 @@
+<domain xmlns:qemu='http://libvirt.org/schemas/domain/qemu/1.0' type=''>
+  <name/>
+  <title/>
+  <description/>
+  <uuid/>
+  <memory/>
+  <vcpu>1</vcpu>
+
+
+  <cpu mode='host-model'>
+      <model fallback='allow'/>
+  </cpu>
+
+
+  <os>
+        <type>hvm</type>
+    <kernel/>
+    <initrd/>
+    <cmdline/>
+  </os>
+  <features>
+    <acpi/>
+    <apic/>
+    <pae/>
+  </features>
+  <clock offset='utc'/>
+  <devices>
+
+
+    <serial type='pty'>
+      <target port='0'/>
+    </serial>
+    <console type='pty'>
+      <target port='0'/>
+    </console>
+
+
+    <input bus='ps2' type='mouse'/>
+
+      <graphics autoport='yes' keymap='en-us' listen='127.0.0.1' port='-1' type='vnc'/>
+      <video>
+        <model heads='1' type='cirrus' vram='9216'/>
+      </video>
+
+
+  <tpm model='tpm-tis'><backend type='passthrough'><device path='/dev/tpm0'/></backend></tpm></devices>
+
+</domain>

spec/unit/action/wait_till_up_spec.rb

@@ -41,6 +41,7 @@ describe VagrantPlugins::ProviderLibvirt::Action::WaitTillUp do
         it 'should exit' do
           expect(app).to_not receive(:call)
           expect(ui).to receive(:info).with('Waiting for domain to get an IP address...')
+          expect(logger).to receive(:debug).with(/Searching for IP for MAC address: .*/)
           expect(subject.call(env)).to be_nil
         end
       end
@@ -56,7 +57,6 @@ describe VagrantPlugins::ProviderLibvirt::Action::WaitTillUp do
           expect(app).to_not receive(:call)
           expect(ui).to receive(:info).with('Waiting for domain to get an IP address...')
           expect(ui).to receive(:info).with('Waiting for SSH to become available...')
-          logger = subject.instance_variable_get(:@logger)
           expect(logger).to receive(:debug).with(/Searching for IP for MAC address: .*/)
           expect(logger).to receive(:info).with('Got IP address 192.168.121.2')
           expect(logger).to receive(:info).with(/Time for getting IP: .*/)
@@ -77,6 +77,10 @@ describe VagrantPlugins::ProviderLibvirt::Action::WaitTillUp do
         expect(app).to receive(:call)
         expect(ui).to receive(:info).with('Waiting for domain to get an IP address...')
         expect(ui).to receive(:info).with('Waiting for SSH to become available...')
+        expect(logger).to receive(:debug).with(/Searching for IP for MAC address: .*/)
+        expect(logger).to receive(:info).with('Got IP address 192.168.121.2')
+        expect(logger).to receive(:info).with(/Time for getting IP: .*/)
+        expect(logger).to receive(:info).with(/Time for SSH ready: .*/)
         expect(env[:machine].communicate).to receive(:ready?).and_return(true)
         expect(subject.call(env)).to be_nil
       end