Update the Virtualization Test to Clean up Logs (Bugfix) (#743)

* Update the Virtualization Test Clean up Logs

I have added an option to reduce the error messages shown in the logs
while the script checks to see if the virtual machine has booted.
(Bugfix) for issue #695

Updated suggested changes in PR review
- Changed error_msgs to log_stderr
- Replaced elif with a cleaner if statement

* Add a few tests to virtualization.py

Add test for cleanup

Fully test start_vm

Partially test setup

Add no stderr test

* Updated tests and small refactoring of start_vm

* Black run_command and setup

* Recover deleted minor tests

---------

Co-authored-by: Hook25 <massimiliano.girardi@canonical.com>

providers/base/bin/virtualization.py

@@ -734,22 +734,26 @@ def __init__(self, template=None, image=None):
  self.default_remote = "ubuntu:"
  self.os_version = get_release_to_test()
 
- def run_command(self, cmd):
+ def run_command(self, cmd, log_stderr=True):
  task = RunCommand(cmd)
  if task.returncode != 0:
- logging.error('Command {} returned a code of {}'.format(
- task.cmd, task.returncode))
- logging.error(' STDOUT: {}'.format(task.stdout))
- logging.error(' STDERR: {}'.format(task.stderr))
+ logging.error(
+ "Command {} returned a code of {}".format(
+ task.cmd, task.returncode
+ )
+ )
+ logging.error(" STDOUT: {}".format(task.stdout))
+ if log_stderr:
+ logging.error(" STDERR: {}".format(task.stderr))
  return False
  else:
- logging.debug('Command {}:'.format(task.cmd))
- if task.stdout != '':
- logging.debug(' STDOUT: {}'.format(task.stdout))
- elif task.stderr != '':
- logging.debug(' STDERR: {}'.format(task.stderr))
- else:
- logging.debug(' Command returned no output')
+ logging.debug("Command {}:".format(task.cmd))
+ if task.stdout != "":
+ logging.debug(" STDOUT: {}".format(task.stdout))
+ if task.stderr and log_stderr:
+ logging.debug(" STDERR: {}".format(task.stderr))
+ if not (task.stderr or task.stdout):
+ logging.debug(" Command returned no output")
  return True
 
  def setup(self):
@@ -842,59 +846,57 @@ def cleanup(self):
  Clean up test files an Virtual Machines created
  """
  logging.debug('Cleaning up images and VMs created during test')
- self.run_command('lxc image delete {}'.format(self.image_alias))
- self.run_command('lxc delete --force {}'.format(self.name))
+ self.run_command('lxc image delete {}'.format(self.image_alias), False)
+ self.run_command('lxc delete --force {}'.format(self.name), False)
 
  def start_vm(self):
  """
  Creates an lxd virtual machine and performs the test
  """
- wait_interval = 5
- test_interval = 300
 
- result = self.setup()
- if not result:
+ if not self.setup():
  logging.error("One or more setup stages failed.")
  return False
 
  # Create Virtual Machine
  logging.debug("Launching Virtual Machine")
  if not self.image_url and not self.template_url:
- logging.debug("No local image available, attempting to "
- "import from default remote.")
- cmd = ('lxc init {}{} {} --vm '.format(
- self.default_remote, self.os_version, self.name))
+ logging.debug(
+ "No local image available, attempting to "
+ "import from default remote."
+ )
+ cmd = "lxc init {}{} {} --vm ".format(
+ self.default_remote, self.os_version, self.name
+ )
  else:
- cmd = ('lxc init {} {} --vm'.format(self.image_alias, self.name))
+ cmd = "lxc init {} {} --vm".format(self.image_alias, self.name)
 
  if not self.run_command(cmd):
  return False
 
  logging.debug("Start VM:")
- cmd = ("lxc start {} ".format(self.name))
- if not self.run_command(cmd):
+ if not self.run_command("lxc start {} ".format(self.name)):
  return False
 
  logging.debug("Virtual Machine listing:")
- cmd = ("lxc list")
- if not self.run_command(cmd):
+ if not self.run_command("lxc list"):
  return False
 
  logging.debug("Wait for vm to boot")
- check_vm = 0
- while check_vm < test_interval:
+ wait_interval = 5
+ max_wait_duration = 300
+ time_waited = 0
+ while time_waited < max_wait_duration:
  time.sleep(wait_interval)
- cmd = ("lxc exec {} -- lsb_release -a".format(self.name))
- if self.run_command(cmd):
+ cmd = "lxc exec {} -- lsb_release -a".format(self.name)
+ if self.run_command(cmd, False):
  print("Vm started and booted successfully")
  return True
- else:
- logging.debug("Re-verify VM booted")
- check_vm = check_vm + wait_interval
+ logging.debug("Re-verify VM booted")
+ time_waited += wait_interval
 
  logging.debug("testing vm failed")
- if check_vm == test_interval:
- return False
+ return False
 
 
 def test_lxd_vm(args):

providers/base/tests/test_virtualization.py

@@ -0,0 +1,220 @@
+#!/usr/bin/env python3
+# encoding: utf-8
+# Copyright 2024 Canonical Ltd.
+# Written by:
+# Massimiliano Girardi <massimiliano.girardi@canonical.com>
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU General Public License version 3,
+# as published by the Free Software Foundation.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with this program. If not, see <http://www.gnu.org/licenses/>.
+
+import itertools
+from unittest import TestCase
+from unittest.mock import patch, MagicMock
+
+from virtualization import LXDTest_vm
+
+
+class TestLXDTest_vm(TestCase):
+ @patch("virtualization.logging")
+ @patch("virtualization.RunCommand")
+ def test_run_command_no_stderr(self, run_command_mock, logging_mock):
+ task = run_command_mock()
+ task.returncode = 0
+ task.stdout = "abc"
+ task.stderr = None
+
+ command_result = LXDTest_vm.run_command(
+ MagicMock(), "command", log_stderr=True
+ )
+
+ self.assertTrue(logging_mock.debug.called)
+ self.assertTrue(command_result)
+
+ @patch("virtualization.logging")
+ @patch("virtualization.RunCommand")
+ def test_run_command_no_log_stderr(self, run_command_mock, logging_mock):
+ task = run_command_mock()
+ task.returncode = 1
+ task.stdout = "abc"
+ task.stderr = None
+
+ command_result = LXDTest_vm.run_command(
+ MagicMock(), "command", log_stderr=False
+ )
+
+ self.assertFalse(command_result)
+
+ @patch("virtualization.logging")
+ @patch("virtualization.RunCommand")
+ def test_run_command_error(self, run_command_mock, logging_mock):
+ task = run_command_mock()
+ task.returncode = 1
+ task.stdout = "abc"
+ task.stderr = "some error"
+
+ command_result = LXDTest_vm.run_command(
+ MagicMock(), "command", log_stderr=True
+ )
+
+ self.assertTrue(logging_mock.error.called)
+ self.assertFalse(command_result)
+
+ @patch("virtualization.logging")
+ @patch("virtualization.RunCommand")
+ def test_run_command_ok(self, run_command_mock, logging_mock):
+ task = run_command_mock()
+ task.returncode = 0
+ task.stdout = "abc"
+ task.stderr = "some error"
+
+ command_result = LXDTest_vm.run_command(
+ MagicMock(), "command", log_stderr=True
+ )
+
+ self.assertTrue(logging_mock.debug.called)
+ self.assertTrue(command_result)
+
+ @patch("virtualization.logging")
+ @patch("virtualization.RunCommand")
+ def test_run_command_ok_no_stdout(self, run_command_mock, logging_mock):
+ task = run_command_mock()
+ task.returncode = 0
+ task.stdout = ""
+ task.stderr = "some error"
+
+ command_result = LXDTest_vm.run_command(
+ MagicMock(), "command", log_stderr=True
+ )
+
+ self.assertTrue(logging_mock.debug.called)
+ self.assertTrue(command_result)
+
+
+ @patch("virtualization.logging")
+ def test_cleanup(self, logging_mock):
+ self_mock = MagicMock()
+ LXDTest_vm.cleanup(self_mock)
+
+ self.assertTrue(self_mock.run_command.called)
+
+ @patch("virtualization.logging")
+ def test_start_vm_fail_setup(self, logging_mock):
+ self_mock = MagicMock()
+ self_mock.setup.return_value = False
+
+ start_result = LXDTest_vm.start_vm(self_mock)
+
+ self.assertTrue(self_mock.setup.called)
+ self.assertTrue(logging_mock.error.called)
+ self.assertFalse(start_result)
+
+ @patch("virtualization.logging")
+ def test_start_vm_fail_init_no_img_alias(self, logging_mock):
+ self_mock = MagicMock()
+ self_mock.setup.return_value = True
+ self_mock.image_url = None
+ self_mock.template_url = None
+ self_mock.default_remote = "def remote"
+ self_mock.os_version = "os version"
+ self_mock.name = "name"
+ self_mock.run_command.side_effect = [False]
+
+ start_result = LXDTest_vm.start_vm(self_mock)
+
+ self.assertTrue(self_mock.setup.called)
+ self.assertFalse(start_result)
+
+ @patch("virtualization.logging")
+ def test_start_vm_fail_init_img_alias(self, logging_mock):
+ self_mock = MagicMock()
+ self_mock.setup.return_value = True
+ self_mock.image_url = "image url"
+ self_mock.template_url = "template url"
+ self_mock.name = "vm name"
+ self_mock.run_command.side_effect = [False]
+
+ start_result = LXDTest_vm.start_vm(self_mock)
+
+ self.assertTrue(self_mock.setup.called)
+ self.assertFalse(start_result)
+
+ @patch("virtualization.logging")
+ def test_start_vm_fail_start(self, logging_mock):
+ self_mock = MagicMock()
+ self_mock.setup.return_value = True
+ self_mock.image_url = "image url"
+ self_mock.template_url = "template url"
+ self_mock.name = "vm name"
+ self_mock.run_command.side_effect = [True, False]
+
+ start_result = LXDTest_vm.start_vm(self_mock)
+
+ self.assertTrue(self_mock.setup.called)
+ self.assertFalse(start_result)
+
+ @patch("virtualization.logging")
+ def test_start_vm_fail_list(self, logging_mock):
+ self_mock = MagicMock()
+ self_mock.setup.return_value = True
+ self_mock.image_url = "image url"
+ self_mock.template_url = "template url"
+ self_mock.name = "vm name"
+ self_mock.run_command.side_effect = [True, True, False]
+
+ start_result = LXDTest_vm.start_vm(self_mock)
+
+ self.assertTrue(self_mock.setup.called)
+ self.assertFalse(start_result)
+
+ @patch("time.sleep")
+ @patch("virtualization.logging")
+ def test_start_vm_fail_exec(self, logging_mock, time_sleep_mock):
+ self_mock = MagicMock()
+ self_mock.setup.return_value = True
+ self_mock.image_url = "image url"
+ self_mock.template_url = "template url"
+ self_mock.name = "vm name"
+ self_mock.run_command.side_effect = itertools.chain(
+ [True, True, True], itertools.repeat(False)
+ )
+
+ start_result = LXDTest_vm.start_vm(self_mock)
+
+ self.assertTrue(self_mock.setup.called)
+ self.assertFalse(start_result)
+
+ @patch("time.sleep")
+ @patch("virtualization.print")
+ @patch("virtualization.logging")
+ def test_start_vm_success(self, logging_mock, print_mock, time_sleep_mock):
+ self_mock = MagicMock()
+ self_mock.setup.return_value = True
+ self_mock.image_url = "image url"
+ self_mock.template_url = "template url"
+ self_mock.name = "vm name"
+ self_mock.run_command.side_effect = [True, True, True, True]
+
+ start_result = LXDTest_vm.start_vm(self_mock)
+
+ self.assertTrue(self_mock.setup.called)
+ self.assertTrue(start_result)
+ self.assertTrue(print_mock.called)
+
+ def test_setup_failure(self):
+ self_mock = MagicMock()
+ self_mock.run_command.return_value = False
+ self_mock.template_url = None
+ self_mock.image_url = None
+
+ setup_return = LXDTest_vm.setup(self_mock)
+
+ self.assertFalse(setup_return)