From b5768ae359dde41312ba99fe7352f1d1edcf4ac2 Mon Sep 17 00:00:00 2001
From: Daniel Caires <daniel.caires@encora.com>
Date: Mon, 4 Sep 2023 13:57:58 -0300
Subject: [PATCH] Review LOG levels

Adjust LOG levels throughout the code.

Story: 2005051
Task: 48516

Change-Id: Ie54a0d6a50c373ebc8b1d272aa5b574d5821b399
Signed-off-by: Daniel Caires <daniel.caires@encora.com>
---
 virtualbox/pybox/helper/host_helper.py        |  4 +--
 virtualbox/pybox/helper/install_lab.py        |  2 +-
 .../pybox/helper/tests/test_install_vbox.py   | 25 ++++++++-------
 .../pybox/helper/tests/test_vboxmanage.py     | 14 ++++----
 virtualbox/pybox/helper/vboxmanage.py         |  4 +--
 virtualbox/pybox/install_vbox.py              | 32 +++++++++----------
 virtualbox/pybox/tests/test_install_vbox.py   | 11 ++++---
 virtualbox/pybox/utils/sftp.py                |  2 +-
 8 files changed, 51 insertions(+), 43 deletions(-)

diff --git a/virtualbox/pybox/helper/host_helper.py b/virtualbox/pybox/helper/host_helper.py
index 127cfca..ad4c262 100644
--- a/virtualbox/pybox/helper/host_helper.py
+++ b/virtualbox/pybox/helper/host_helper.py
@@ -32,7 +32,7 @@ def unlock_host(stream, hostname):
     try:
         serial.expect_bytes(stream, "locked")
     except streamexpect.ExpectTimeout:
-        LOG.info("Host %s not locked", hostname)
+        LOG.error("Host %s not locked", hostname)
         return 1
 
     LOG.info("#### Unlock %s", hostname)
@@ -58,7 +58,7 @@ def lock_host(stream, hostname):
     try:
         serial.expect_bytes(stream, "unlocked")
     except streamexpect.ExpectTimeout:
-        LOG.info("Host %s not unlocked", hostname)
+        LOG.error("Host %s not unlocked", hostname)
         return 1
 
     LOG.info("Lock %s", hostname)
diff --git a/virtualbox/pybox/helper/install_lab.py b/virtualbox/pybox/helper/install_lab.py
index 6f0fabb..7a72ab7 100644
--- a/virtualbox/pybox/helper/install_lab.py
+++ b/virtualbox/pybox/helper/install_lab.py
@@ -53,7 +53,7 @@ def config_controller(stream, password):
     serial.send_bytes(stream, cmd, expect_prompt=False, log=False)
     ret = serial.expect_bytes(stream, "[0]", timeout=HostTimeout.NORMAL_OP, log=False)
     if ret != 0:
-        LOG.info("Configuration failed. Exiting installer.")
+        LOG.error("Configuration failed. Exiting installer.")
         raise SystemExit("Configcontroller failed")
     LOG.info("Successful bootstrap ansible playbook execution")
 
diff --git a/virtualbox/pybox/helper/tests/test_install_vbox.py b/virtualbox/pybox/helper/tests/test_install_vbox.py
index dad8148..54d6b96 100644
--- a/virtualbox/pybox/helper/tests/test_install_vbox.py
+++ b/virtualbox/pybox/helper/tests/test_install_vbox.py
@@ -45,7 +45,8 @@ class CreateportforwardTestCase(unittest.TestCase):
     @patch("helper.vboxmanage.vboxmanage_addportforward")
     @patch("helper.vboxmanage.vboxmanage_deleteportforward", return_value=None)
     @patch('utils.install_log.LOG.info')
-    def test_rewrite_rule_yes_to_all(self, mock_log, mock_deleteport, mock_addport, mock_getrule, mock_v_box_options):
+    @patch('utils.install_log.LOG.warning')
+    def test_rewrite_rule_yes_to_all(self, mock_warning, mock_info,  mock_deleteport, mock_addport, mock_getrule, mock_v_box_options):
         """
         Test create_port_forward method that fails to create rule and the installer was called with --y (yes to all) as an argument
         """
@@ -59,9 +60,9 @@ class CreateportforwardTestCase(unittest.TestCase):
         result = create_port_forward(self.hostname, self.network, self.local_port, self.guest_port, self.guest_ip)
 
         # Assert
-        mock_log.assert_any_call(
+        mock_warning.assert_any_call(
             "Trying to create a port-forwarding rule with port: %s, but it is already in use with rule name: %s", "8080", "Rule1")
-        mock_log.assert_any_call("Rewriting portforwarding rule...")
+        mock_info.assert_any_call("Rewriting portforwarding rule...")
         mock_getrule.assert_called_once_with('NatNetwork', '8080')
         mock_deleteport.assert_called_once_with('Rule1', 'NatNetwork')
         mock_addport.assert_called_with('TestVM', '8080', '10.10.10.1', '80', 'NatNetwork')
@@ -72,7 +73,7 @@ class CreateportforwardTestCase(unittest.TestCase):
     @patch("helper.vboxmanage.vboxmanage_getrulename")
     @patch("helper.vboxmanage.vboxmanage_addportforward")
     @patch("helper.vboxmanage.vboxmanage_deleteportforward", return_value=None)
-    @patch('utils.install_log.LOG.info')
+    @patch('utils.install_log.LOG.warning')
     def test_rewrite_rule(self, mock_log, mock_deleteport, mock_addport, mock_getrule, mock_y_n_prompt):
         """
         Test create_port_forward method that fails to create rule and the user input 'y' to rewrite the existing rule
@@ -99,7 +100,8 @@ class CreateportforwardTestCase(unittest.TestCase):
     @patch("helper.vboxmanage.vboxmanage_getrulename")
     @patch("helper.vboxmanage.vboxmanage_addportforward")
     @patch('utils.install_log.LOG.info')
-    def test_dont_rewrite_rule(self, mock_log, mock_addport, mock_getrule,mock_y_n_prompt):
+    @patch('utils.install_log.LOG.warning')
+    def test_dont_rewrite_rule(self, mock_warning, mock_info, mock_addport, mock_getrule,mock_y_n_prompt):
         """
         Test create_port_forward method that fails to create rule and the user input 'n' to rewrite the existing rule
         """
@@ -113,9 +115,9 @@ class CreateportforwardTestCase(unittest.TestCase):
         result = create_port_forward(self.hostname, self.network, self.local_port, self.guest_port, self.guest_ip)
 
         # Assert
-        mock_log.assert_any_call(
+        mock_warning.assert_any_call(
             "Trying to create a port-forwarding rule with port: %s, but it is already in use with rule name: %s", "8080", "Rule1")
-        mock_log.assert_any_call("Ignoring the creation of the port-forward rule and continuing installation!")
+        mock_info.assert_any_call("Ignoring the creation of the port-forward rule and continuing installation!")
 
         mock_getrule.assert_called_once_with('NatNetwork', '8080')
         mock_addport.assert_called_once_with('TestVM', '8080', '10.10.10.1', '80', 'NatNetwork')
@@ -124,9 +126,10 @@ class CreateportforwardTestCase(unittest.TestCase):
 
     @patch("helper.vboxmanage.vboxmanage_getrulename")
     @patch("helper.vboxmanage.vboxmanage_addportforward")
-    @patch('utils.install_log.LOG.info')
+    @patch('utils.install_log.LOG.error')
+    @patch('utils.install_log.LOG.critical')
     @patch("sys.exit")
-    def test_norule(self, mock_exit, mock_log, mock_addport, mock_getrule):
+    def test_norule(self, mock_exit, mock_critical, mock_error, mock_addport, mock_getrule):
         """
         Test create_port_forward method that fails to create rule and no existing rule is found
         """
@@ -144,9 +147,9 @@ class CreateportforwardTestCase(unittest.TestCase):
         # Assert
         self.assertEqual(cm.exception.code, 1)
 
-        mock_log.assert_any_call(
+        mock_critical.assert_any_call(
             "Could not add a port-forwarding rule using port %s, and could not find any rule already using it. Check the Nat Network and/or local port.", "8080")
-        mock_log.assert_any_call("Aborting!")
+        mock_error.assert_any_call("Aborting!")
 
 
 if __name__ == '__main__':
diff --git a/virtualbox/pybox/helper/tests/test_vboxmanage.py b/virtualbox/pybox/helper/tests/test_vboxmanage.py
index 4d08d03..85e1ab9 100644
--- a/virtualbox/pybox/helper/tests/test_vboxmanage.py
+++ b/virtualbox/pybox/helper/tests/test_vboxmanage.py
@@ -1352,7 +1352,8 @@ class VboxmanageAddportforwardTestCase(unittest.TestCase):
 
     @patch('subprocess.check_output')
     @patch('utils.install_log.LOG.info')
-    def test_vboxmanage_addportforward_error(self, mock_log, mock_check_output):
+    @patch('utils.install_log.LOG.error')
+    def test_vboxmanage_addportforward_error(self, mock_error, mock_info, mock_check_output):
         """
         Test vboxmanage_addportforward method with error
         """
@@ -1365,9 +1366,9 @@ class VboxmanageAddportforwardTestCase(unittest.TestCase):
                                            self.network)
 
         # Assert
-        mock_log.assert_any_call(
+        mock_info.assert_any_call(
             "Creating port-forwarding rule to: %s", "rule1:tcp:[]:8080:[10.10.10.1]:80")
-        mock_log.assert_any_call(
+        mock_error.assert_any_call(
             "Error while trying to create port-forwarding rule. Continuing installation!")
 
         mock_check_output.assert_called_once_with([
@@ -1429,7 +1430,8 @@ class VboxmanageDeleteportforwardTestCase(unittest.TestCase):
 
     @patch('subprocess.check_output')
     @patch('utils.install_log.LOG.info')
-    def test_vboxmanage_deleteportforward_error(self, mock_log, mock_check_output):
+    @patch('utils.install_log.LOG.error')
+    def test_vboxmanage_deleteportforward_error(self, mock_error, mock_info, mock_check_output):
         """
         Test vboxmanage_deleteportforward method with error
         """
@@ -1441,9 +1443,9 @@ class VboxmanageDeleteportforwardTestCase(unittest.TestCase):
         result = vboxmanage.vboxmanage_deleteportforward(self.rule_name, self.network)
 
         # Assert
-        mock_log.assert_any_call(
+        mock_info.assert_any_call(
             "Removing previous forwarding rule '%s' from NAT network '%s'", "rule1", "NatNetwork")
-        mock_log.assert_any_call(
+        mock_error.assert_any_call(
             "Error while trying to delete port-forwarding rule. Continuing installation!")
 
         mock_check_output.assert_called_once_with([
diff --git a/virtualbox/pybox/helper/vboxmanage.py b/virtualbox/pybox/helper/vboxmanage.py
index c6ba75b..c8d8b3e 100644
--- a/virtualbox/pybox/helper/vboxmanage.py
+++ b/virtualbox/pybox/helper/vboxmanage.py
@@ -865,7 +865,7 @@ def vboxmanage_addportforward(rule_name, local_port, guest_ip, guest_port, netwo
     try:
         subprocess.check_output(cmd, stderr=subprocess.STDOUT)
     except subprocess.CalledProcessError:
-        LOG.info("Error while trying to create port-forwarding rule. Continuing installation!")
+        LOG.error("Error while trying to create port-forwarding rule. Continuing installation!")
         return False
     return True
 
@@ -900,4 +900,4 @@ def vboxmanage_deleteportforward(rule_name, network):
     try:
         subprocess.check_output(cmd, stderr=subprocess.STDOUT)
     except subprocess.CalledProcessError:
-        LOG.info("Error while trying to delete port-forwarding rule. Continuing installation!")
+        LOG.error("Error while trying to delete port-forwarding rule. Continuing installation!")
diff --git a/virtualbox/pybox/install_vbox.py b/virtualbox/pybox/install_vbox.py
index 5347db2..0fc72df 100755
--- a/virtualbox/pybox/install_vbox.py
+++ b/virtualbox/pybox/install_vbox.py
@@ -208,7 +208,7 @@ def install_controller_0(cont0_stream, menu_select_dict, network_dict):
             "login:",
             timeout=HostTimeout.INSTALL)
     except Exception as exception:  # pylint: disable=E0012, W0703
-        LOG.info("Connection failed for controller-0 with %s", exception)
+        LOG.exception("Connection failed for controller-0 with %s", exception)
         # Sometimes we get UnicodeDecodeError exception due to the output
         # of installation. So try one more time maybe
         LOG.info("So ignore the exception and wait for controller-0 to be installed again.")
@@ -246,7 +246,7 @@ def delete_lab(labname):
     node_list = vboxmanage.get_all_vms(labname, option="vms")
 
     if len(node_list) != 0:
-        LOG.info("This will delete lab %s with vms: %s", labname, node_list)
+        LOG.warning("This will delete lab %s with vms: %s", labname, node_list)
         #LOG.info("Continue? (y/N)")
         if yes_no_prompt("Delete lab?"):
             LOG.info("#### Deleting lab %s.", labname)
@@ -268,7 +268,7 @@ def get_disk_sizes(comma_list):
     for size in sizes:
         val = int(size)
         if val < 0:
-            LOG.info("Disk sizes must be a comma separated list of positive integers.")
+            LOG.error("Disk sizes must be a comma separated list of positive integers.")
             raise ValueError("Disk sizes must be a comma separated list of positive integers.")
     return sizes
 
@@ -313,13 +313,13 @@ def create_port_forward(hostname, network, local_port, guest_port, guest_ip):
         ):
         rule_name = vboxmanage.vboxmanage_getrulename(network, local_port)
         if not rule_name:
-            LOG.info(
+            LOG.critical(
                 "Could not add a port-forwarding rule using port %s, "
                 "and could not find any rule already using it. "
                 "Check the Nat Network and/or local port.", local_port)
-            LOG.info("Aborting!")
+            LOG.error("Aborting!")
             sys.exit(1)
-        LOG.info(
+        LOG.warning(
             "Trying to create a port-forwarding rule with port: %s, "
             "but it is already in use with rule name: %s",
             local_port,
@@ -706,7 +706,7 @@ def wait_for_hosts(
     start_time = time.time()
     while hostnames:
         if (time.time() - start_time) > HostTimeout.HOST_INSTALL:
-            LOG.info("VMs not booted in %s, aborting: %s", timeout, hostnames)
+            LOG.error("VMs not booted in %s, aborting: %s", timeout, hostnames)
             raise TimeoutError(f"VMs failed to go {status}!")
         # Get host list
         host_statuses, _, _ = run_ssh_cmd(
@@ -719,7 +719,7 @@ def wait_for_hosts(
                 if host in host_status and status in host_status:
                     hostnames.remove(host)
         if hostnames:
-            LOG.info("Hosts not %s: %s", status, hostnames)
+            LOG.warning("Hosts not %s: %s", status, hostnames)
             LOG.info("Waiting %s sec before re-checking host status.", interval)
             time.sleep(interval)
 
@@ -815,7 +815,7 @@ def set_serial_prompt_mode(stream, mode):
         if serial.expect_bytes(stream, "ogin:", fail_ok=True, timeout=4):
             serial.send_bytes(stream, "exit\n", expect_prompt=False)
             if serial.expect_bytes(stream, "ogin:", fail_ok=True, timeout=4):
-                LOG.info("Expected login prompt, connect to console" \
+                LOG.error("Expected login prompt, connect to console" \
                          "stop any running processes and log out.")
                 raise RuntimeError("Failure getting login prompt on serial console!")
         serial.send_bytes(
@@ -863,7 +863,7 @@ def serial_prompt_mode(mode):
             try:
                 set_serial_prompt_mode(kwargs['stream'], mode)
             except:  # pylint: disable=bare-except
-                LOG.info("Serial console login as '%s' failed. Retrying once.", mode)
+                LOG.warning("Serial console login as '%s' failed. Retrying once.", mode)
                 set_serial_prompt_mode(kwargs['stream'], mode)
             return func(*args, **kwargs)
 
@@ -1199,7 +1199,7 @@ def stage_rsync_config():
     """
 
     if not V_BOX_OPTIONS.config_files_dir and not V_BOX_OPTIONS.config_files_dir_dont_follow_links:
-        LOG.info("No rsync done! Please set config-files-dir "
+        LOG.warning("No rsync done! Please set config-files-dir "
                  "and/or config-files-dir-dont-follow-links")
         return
 
@@ -1268,7 +1268,7 @@ def _run_lab_setup(ssh_client):
 
     if exitcode != 0:
         msg = f"Lab setup failed, expecting exit code of 0 but got {exitcode}."
-        LOG.info(msg)
+        LOG.error(msg)
         raise RuntimeError(msg)
 
 
@@ -1866,7 +1866,7 @@ def get_custom_script_options(options_list):
     not_allowed = ['\n', ' ', '*']
     for char in not_allowed:
         if char in options_list:
-            LOG.info("Char '%s' not allowed in options list: %s.", char, options_list)
+            LOG.error("Char '%s' not allowed in options list: %s.", char, options_list)
             raise TypeError("Char not allowed in options_list")
 
     # get options
@@ -2579,8 +2579,8 @@ if __name__ == "__main__":
             if stage not in AVAILABLE_STAGES:
                 invalid_stages.append(stage)
             if invalid_stages:
-                LOG.info("Following custom stages are not supported: %s.\n\
-                         Choose from: %s", invalid_stages, AVAILABLE_STAGES)
+                LOG.warning("Following custom stages are not supported: %s.\n" \
+                         "Choose from: %s", invalid_stages, AVAILABLE_STAGES)
                 sys.exit(1)
     else:
         # List all stages between 'from-stage' to 'to-stage'
@@ -2629,7 +2629,7 @@ if __name__ == "__main__":
         except Exception as stg_exc:
             stg_duration = time.time() - stg_start_time
             kpi.set_kpi_metric(stage, stg_duration)
-            LOG.info("INSTALL FAILED, ABORTING!")
+            LOG.error("INSTALL FAILED, ABORTING!")
             kpi.print_kpi_metrics()
             LOG.info("Exception details: %s", repr(stg_exc))
             raise
diff --git a/virtualbox/pybox/tests/test_install_vbox.py b/virtualbox/pybox/tests/test_install_vbox.py
index b92cf3a..d4f1f73 100644
--- a/virtualbox/pybox/tests/test_install_vbox.py
+++ b/virtualbox/pybox/tests/test_install_vbox.py
@@ -282,13 +282,14 @@ class InstallController0TestCase(unittest.TestCase):
         )
 
     @patch("serial.LOG.info")
+    @patch("serial.LOG.exception")
     @patch("install_vbox.serial")
     @patch("install_vbox.host_helper")
     @patch("install_vbox.time")
     @patch("install_vbox.menu_selector")
     @patch("install_vbox.setup_networking")
     def test_install_controller_0_exception(
-        self, mock_setup_networking, mock_menu_selector, mock_time, mock_host_helper, mock_serial, mock_log_info
+        self, mock_setup_networking, mock_menu_selector, mock_time, mock_host_helper, mock_serial, mock_log_exception, mock_log_info
     ):
         """
         Test install_controller_0 when an exception occurs during login
@@ -308,7 +309,8 @@ class InstallController0TestCase(unittest.TestCase):
         mock_setup_networking.assert_called_once()
         mock_host_helper.change_password.assert_called_once()
         mock_host_helper.disable_logout.assert_called_once()
-        self.assertEqual(mock_log_info.call_count, 4)
+        self.assertEqual(mock_log_info.call_count, 3)
+        self.assertEqual(mock_log_exception.call_count, 1)
 
 
 class DeleteLabTestCase(unittest.TestCase):
@@ -339,11 +341,12 @@ class DeleteLabTestCase(unittest.TestCase):
         # Assert
         mock_vboxmanage.get_all_vms.assert_called_once_with(self.mock_labname, option="vms")
         mock_log.info.assert_has_calls([
-            call("This will delete lab %s with vms: %s", self.mock_labname, self.mock_node_list),
             #call("Continue? (y/N)"),
             call("#### Deleting lab %s.", self.mock_labname),
             call("VMs in lab: %s.", self.mock_node_list),
         ])
+        mock_log.warning.assert_called_once_with(
+            "This will delete lab %s with vms: %s", self.mock_labname, self.mock_node_list)
         mock_vboxmanage.vboxmanage_controlvms.assert_called_once_with(self.mock_node_list, "poweroff")
         mock_time.sleep.assert_called_once_with(2)
         mock_vboxmanage.vboxmanage_deletevms.assert_called_once_with(self.mock_node_list)
@@ -430,7 +433,7 @@ class GetDiskSizesTestCase(unittest.TestCase):
             install_vbox.get_disk_sizes(invalid_input)
 
         self.assertTrue("Disk sizes must be a comma separated list of positive integers." in str(context.exception))
-        mock_log.info.assert_called_once_with("Disk sizes must be a comma separated list of positive integers.")
+        mock_log.error.assert_called_once_with("Disk sizes must be a comma separated list of positive integers.")
 
 
 class TestCreateLab(unittest.TestCase):
diff --git a/virtualbox/pybox/utils/sftp.py b/virtualbox/pybox/utils/sftp.py
index 0c41449..3118a37 100644
--- a/virtualbox/pybox/utils/sftp.py
+++ b/virtualbox/pybox/utils/sftp.py
@@ -45,7 +45,7 @@ def sftp_send(source, destination, client_dict):
             sftp_client = ssh_client.open_sftp()
             retry = 8
         except Exception:  # pylint: disable=W0703
-            LOG.info("******* try again")
+            LOG.warning("******* try again")
             retry += 1
             LOG.info("Waiting 10s")
             time.sleep(10)