fix(tests): switch to Info log level

Instead of fluding the console with debug logs from
vsock and other places for all VMs, only do this for api tests.

Signed-off-by: Egor Lazarchuk <yegorlz@amazon.co.uk>

Author: ShadowCurse

tests/framework/microvm.py

@@ -637,7 +637,7 @@ def spawn(
         self,
         log_file="fc.log",
         serial_out_path="serial.log",
-        log_level="Debug",
+        log_level="Info",
         log_show_level=False,
         log_show_origin=False,
         metrics_path="fc.ndjson",

tests/integration_tests/functional/test_api.py

@@ -34,7 +34,8 @@ def test_api_happy_start(uvm_plain):
     Test that a regular microvm API config and boot sequence works.
     """
     test_microvm = uvm_plain
-    test_microvm.spawn()
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
 
     # Set up the microVM with 2 vCPUs, 256 MiB of RAM and
     # a root file system with the rw permission.
@@ -54,7 +55,8 @@ def test_drive_io_engine(uvm_plain, io_engine):
     support the given type and that FC returns an error otherwise.
     """
     test_microvm = uvm_plain
-    test_microvm.spawn()
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
 
     test_microvm.basic_config(add_root_device=False)
     test_microvm.add_net_iface()
@@ -82,7 +84,8 @@ def test_api_put_update_pre_boot(uvm_plain, io_engine):
     Tests updates on drives, boot source and machine config.
     """
     test_microvm = uvm_plain
-    test_microvm.spawn()
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
 
     # Set up the microVM with 2 vCPUs, 256 MiB of RAM  and
     # a root file system with the rw permission.
@@ -177,7 +180,8 @@ def test_net_api_put_update_pre_boot(uvm_plain):
     Test PUT updates on network configurations before the microvm boots.
     """
     test_microvm = uvm_plain
-    test_microvm.spawn()
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
 
     tap1name = test_microvm.id[:8] + "tap1"
     tap1 = net_tools.Tap(tap1name, test_microvm.netns)
@@ -227,7 +231,8 @@ def test_api_mmds_config(uvm_plain):
     Tests updates on MMDS config before and after attaching a network device.
     """
     test_microvm = uvm_plain
-    test_microvm.spawn()
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
 
     # Set up the microVM with 2 vCPUs, 256 MiB of RAM  and
     # a root file system with the rw permission.
@@ -303,7 +308,8 @@ def test_api_machine_config(uvm_plain):
     Test /machine_config PUT/PATCH scenarios that unit tests can't cover.
     """
     test_microvm = uvm_plain
-    test_microvm.spawn()
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
 
     # Test invalid vcpu count < 0.
     with pytest.raises(RuntimeError):
@@ -417,7 +423,8 @@ def test_negative_machine_config_api(uvm_plain):
     response header should have "Deprecation: true".
     """
     test_microvm = uvm_plain
-    test_microvm.spawn()
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
 
     # Use `cpu_template` field in PUT /machine-config
     response = test_microvm.api.machine_config.put(
@@ -444,7 +451,8 @@ def test_api_cpu_config(uvm_plain, custom_cpu_template):
     Test /cpu-config PUT scenarios.
     """
     test_microvm = uvm_plain
-    test_microvm.spawn()
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
 
     with pytest.raises(RuntimeError):
         test_microvm.api.cpu_config.put(foo=False)
@@ -457,7 +465,8 @@ def test_api_put_update_post_boot(uvm_plain, io_engine):
     Test that PUT updates are rejected after the microvm boots.
     """
     test_microvm = uvm_plain
-    test_microvm.spawn()
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
 
     # Set up the microVM with 2 vCPUs, 256 MiB of RAM  and
     # a root file system with the rw permission.
@@ -517,7 +526,8 @@ def test_rate_limiters_api_config(uvm_plain, io_engine):
     Test the IO rate limiter API config.
     """
     test_microvm = uvm_plain
-    test_microvm.spawn()
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
 
     # Test the DRIVE rate limiting API.
 
@@ -625,7 +635,8 @@ def test_api_patch_pre_boot(uvm_plain, io_engine):
     Test that PATCH updates are not allowed before the microvm boots.
     """
     test_microvm = uvm_plain
-    test_microvm.spawn()
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
 
     # Sets up the microVM with 2 vCPUs, 256 MiB of RAM, 1 network interface
     # and a root file system with the rw permission.
@@ -675,7 +686,8 @@ def test_negative_api_patch_post_boot(uvm_plain, io_engine):
     Test PATCH updates that are not allowed after the microvm boots.
     """
     test_microvm = uvm_plain
-    test_microvm.spawn()
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
 
     # Sets up the microVM with 2 vCPUs, 256 MiB of RAM, 1 network iface and
     # a root file system with the rw permission.
@@ -717,7 +729,8 @@ def test_drive_patch(uvm_plain, io_engine):
     Extensively test drive PATCH scenarios before and after boot.
     """
     test_microvm = uvm_plain
-    test_microvm.spawn()
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
 
     # Sets up the microVM with 2 vCPUs, 256 MiB of RAM and
     # a root file system with the rw permission.
@@ -756,7 +769,8 @@ def test_send_ctrl_alt_del(uvm_plain_any):
     # This relies on the i8042 device and AT Keyboard support being present in
     # the guest kernel.
     test_microvm = uvm_plain_any
-    test_microvm.spawn()
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
 
     test_microvm.basic_config()
     test_microvm.add_net_iface()
@@ -904,7 +918,8 @@ def test_api_version(uvm_plain):
     Test the permanent VM version endpoint.
     """
     test_microvm = uvm_plain
-    test_microvm.spawn()
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
     test_microvm.basic_config()
 
     # Getting the VM version should be available pre-boot.
@@ -965,7 +980,8 @@ def test_api_entropy(uvm_plain):
     Test entropy related API commands.
     """
     test_microvm = uvm_plain
-    test_microvm.spawn()
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
     test_microvm.basic_config()
 
     # Create a new entropy device should be OK.
@@ -986,7 +1002,8 @@ def test_api_memory_hotplug(uvm_plain_6_1):
     Test hotplug related API commands.
     """
     test_microvm = uvm_plain_6_1
-    test_microvm.spawn()
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
     test_microvm.basic_config()
     test_microvm.add_net_iface()
 
@@ -1024,11 +1041,15 @@ def test_api_memory_hotplug(uvm_plain_6_1):
     assert status["requested_size_mib"] == 512
 
 
-def test_api_balloon(uvm_nano):
+def test_api_balloon(uvm_plain):
     """
     Test balloon related API commands.
     """
-    test_microvm = uvm_nano
+    test_microvm = uvm_plain
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
+    test_microvm.basic_config(vcpu_count=2, mem_size_mib=256)
+    test_microvm.add_net_iface()
 
     # Updating an inexistent balloon device should give an error.
     with pytest.raises(RuntimeError):
@@ -1093,7 +1114,8 @@ def test_pmem_api(uvm_plain_any, rootfs):
     """
 
     vm = uvm_plain_any
-    vm.spawn()
+    vm.time_api_requests = True
+    vm.spawn(log_level="Debug")
     vm.basic_config(add_root_device=False)
 
     invalid_pmem_path_on_host = os.path.join(vm.fsfiles, "invalid_scratch")
@@ -1148,11 +1170,17 @@ def test_pmem_api(uvm_plain_any, rootfs):
         vm.api.pmem.put(id="pmem")
 
 
-def test_get_full_config_after_restoring_snapshot(microvm_factory, uvm_nano):
+def test_get_full_config_after_restoring_snapshot(microvm_factory, uvm_plain):
     """
     Test the configuration of a microVM after restoring from a snapshot.
     """
-    net_iface = uvm_nano.add_net_iface()
+
+    test_microvm = uvm_plain
+    test_microvm.time_api_requests = True
+    test_microvm.spawn(log_level="Debug")
+    test_microvm.basic_config(vcpu_count=2, mem_size_mib=256)
+
+    net_iface = test_microvm.add_net_iface()
     cpu_vendor = utils_cpuid.get_cpu_vendor()
 
     setup_cfg = {}
@@ -1171,7 +1199,7 @@ def test_get_full_config_after_restoring_snapshot(microvm_factory, uvm_nano):
     if len(SUPPORTED_CPU_TEMPLATES) != 0:
         setup_cfg["machine-config"]["cpu_template"] = SUPPORTED_CPU_TEMPLATES[0]
 
-    uvm_nano.api.machine_config.patch(**setup_cfg["machine-config"])
+    test_microvm.api.machine_config.patch(**setup_cfg["machine-config"])
 
     setup_cfg["cpu-config"] = None
 
@@ -1182,30 +1210,30 @@ def test_get_full_config_after_restoring_snapshot(microvm_factory, uvm_nano):
             "is_root_device": True,
             "cache_type": "Unsafe",
             "is_read_only": True,
-            "path_on_host": f"/{uvm_nano.rootfs_file.name}",
+            "path_on_host": f"/{test_microvm.rootfs_file.name}",
             "rate_limiter": None,
             "io_engine": "Sync",
             "socket": None,
         }
     ]
 
-    uvm_nano.api.pmem.put(
+    test_microvm.api.pmem.put(
         id="pmem",
-        path_on_host="/" + uvm_nano.rootfs_file.name,
+        path_on_host="/" + test_microvm.rootfs_file.name,
         root_device=False,
         read_only=False,
     )
     setup_cfg["pmem"] = [
         {
             "id": "pmem",
-            "path_on_host": "/" + uvm_nano.rootfs_file.name,
+            "path_on_host": "/" + test_microvm.rootfs_file.name,
             "root_device": False,
             "read_only": False,
         }
     ]
 
     # Add a memory balloon device.
-    uvm_nano.api.balloon.put(amount_mib=1, deflate_on_oom=True)
+    test_microvm.api.balloon.put(amount_mib=1, deflate_on_oom=True)
     setup_cfg["balloon"] = {
         "amount_mib": 1,
         "deflate_on_oom": True,
@@ -1215,15 +1243,15 @@ def test_get_full_config_after_restoring_snapshot(microvm_factory, uvm_nano):
     }
 
     # Add a vsock device.
-    uvm_nano.api.vsock.put(guest_cid=15, uds_path="vsock.sock")
+    test_microvm.api.vsock.put(guest_cid=15, uds_path="vsock.sock")
     setup_cfg["vsock"] = {"guest_cid": 15, "uds_path": "vsock.sock"}
 
     setup_cfg["memory-hotplug"] = {
         "total_size_mib": 1024,
         "block_size_mib": 128,
         "slot_size_mib": 1024,
     }
-    uvm_nano.api.memory_hotplug.put(**setup_cfg["memory-hotplug"])
+    test_microvm.api.memory_hotplug.put(**setup_cfg["memory-hotplug"])
 
     setup_cfg["logger"] = None
     setup_cfg["metrics"] = None
@@ -1232,18 +1260,18 @@ def test_get_full_config_after_restoring_snapshot(microvm_factory, uvm_nano):
         "network_interfaces": [net_iface.dev_name],
     }
 
-    uvm_nano.api.mmds_config.put(**setup_cfg["mmds-config"])
+    test_microvm.api.mmds_config.put(**setup_cfg["mmds-config"])
 
     # Start the microvm.
-    uvm_nano.start()
+    test_microvm.start()
 
     # Add a tx rate limiter to the net device.
     tx_rl = {
         "bandwidth": {"size": 1000000, "refill_time": 100, "one_time_burst": None},
         "ops": None,
     }
 
-    response = uvm_nano.api.network.patch(
+    response = test_microvm.api.network.patch(
         iface_id=net_iface.dev_name, tx_rate_limiter=tx_rl
     )
     setup_cfg["network-interfaces"] = [
@@ -1256,17 +1284,17 @@ def test_get_full_config_after_restoring_snapshot(microvm_factory, uvm_nano):
         }
     ]
 
-    snapshot = uvm_nano.snapshot_full()
+    snapshot = test_microvm.snapshot_full()
     uvm2 = microvm_factory.build_from_snapshot(snapshot)
     expected_cfg = setup_cfg.copy()
 
     # We expect boot-source to be set with the following values
     expected_cfg["boot-source"] = {
-        "kernel_image_path": uvm_nano.get_jailed_resource(uvm_nano.kernel_file),
+        "kernel_image_path": test_microvm.get_jailed_resource(test_microvm.kernel_file),
         "initrd_path": None,
         "boot_args": "reboot=k panic=1 nomodule swiotlb=noforce console=ttyS0",
     }
-    if not uvm_nano.pci_enabled:
+    if not test_microvm.pci_enabled:
         expected_cfg["boot-source"]["boot_args"] += " pci=off"
 
     # no ipv4_address or imds_compat specified during PUT /mmds/config so we expect the default
@@ -1291,10 +1319,11 @@ def test_get_full_config(uvm_plain):
     Test the reported configuration of a microVM configured with all resources.
     """
     test_microvm = uvm_plain
+    test_microvm.time_api_requests = True
 
     expected_cfg = {}
 
-    test_microvm.spawn()
+    test_microvm.spawn(log_level="Debug")
     # Basic config also implies a root block device.
     test_microvm.basic_config(boot_args="", rootfs_io_engine="Sync")
     expected_cfg["machine-config"] = {
@@ -1428,10 +1457,11 @@ def test_map_private_seccomp_regression(uvm_plain):
     killed by the seccomp filter before this PR.
     """
     test_microvm = uvm_plain
+    test_microvm.time_api_requests = True
     test_microvm.jailer.extra_args.update(
         {"http-api-max-payload-size": str(1024 * 1024 * 2)}
     )
-    test_microvm.spawn()
+    test_microvm.spawn(log_level="Debug")
     test_microvm.time_api_request = False
 
     response = test_microvm.api.mmds.get()
@@ -1447,7 +1477,8 @@ def test_negative_snapshot_load_api(microvm_factory):
     Test snapshot load API.
     """
     vm = microvm_factory.build()
-    vm.spawn()
+    vm.time_api_requests = True
+    vm.spawn(log_level="Debug")
 
     # Specifying both `mem_backend` and 'mem_file_path` should fail.
     err_msg = (