diff --git a/.github/workflows/run-nightly-tests.yml b/.github/workflows/run-nightly-tests.yml index 67b947e90e..20081f8f54 100644 --- a/.github/workflows/run-nightly-tests.yml +++ b/.github/workflows/run-nightly-tests.yml @@ -104,7 +104,8 @@ jobs: { "controller" : "${CONTROLLER}", "ns1": "${BDEV0}", - "log_dir": "/nvme-cli/tests/nvmetests/", + "log_dir": "/nvme-cli/tests/nvmetests", + "log_level": "DEBUG", "nvme_bin": "/nvme-cli/.build-ci/nvme" } EOJ diff --git a/libnvme/src/nvme/lib.c b/libnvme/src/nvme/lib.c index d5bc10a097..973dd01bd3 100644 --- a/libnvme/src/nvme/lib.c +++ b/libnvme/src/nvme/lib.c @@ -167,6 +167,8 @@ static int __nvme_transport_handle_open_direct( } if (hdl->ctx->ioctl_probing) { + /* avoid kernel logging 'cmd does not match nsid' */ + dummy.nsid = ns; ret = ioctl(hdl->fd, LIBNVME_IOCTL_ADMIN64_CMD, &dummy); if (ret > 0) { hdl->ioctl_admin64 = true; diff --git a/tests/config.json b/tests/config.json index 098fba807f..facaaa78cb 100644 --- a/tests/config.json +++ b/tests/config.json @@ -1,5 +1,6 @@ { "controller" : "/dev/nvme0", "ns1": "/dev/nvme0n1", - "log_dir": "nvmetests/" + "log_dir": "nvmetests", + "log_level": "DEBUG" } diff --git a/tests/nvme_copy_test.py b/tests/nvme_copy_test.py index f73cd04b1e..38c5805878 100644 --- a/tests/nvme_copy_test.py +++ b/tests/nvme_copy_test.py @@ -16,10 +16,13 @@ """ +import logging import subprocess from nvme_test import TestNVMe +logger = logging.getLogger(__name__) + class TestNVMeCopy(TestNVMe): @@ -41,6 +44,7 @@ def setUp(self): # get host behavior support data get_features_cmd = f"{self.nvme_bin} get-feature {self.ctrl} " + \ "--feature-id=0x16 --data-len=512 --raw-binary" + logger.debug(get_features_cmd) proc = subprocess.Popen(get_features_cmd, shell=True, stdout=subprocess.PIPE, @@ -65,6 +69,7 @@ def setUp(self): proc.communicate(input=data) self.assertEqual(proc.returncode, 0, "Failed to enable cross-namespace copy formats") get_ns_id_cmd = f"{self.nvme_bin} get-ns-id {self.ns1}" + logger.debug(get_ns_id_cmd) proc = subprocess.Popen(get_ns_id_cmd, shell=True, stdout=subprocess.PIPE, @@ -72,6 +77,7 @@ def setUp(self): err = proc.wait() self.assertEqual(err, 0, "ERROR : nvme get-ns-id failed") output = proc.stdout.read() + logger.debug(output) self.ns1_nsid = int(output.strip().split(':')[-1]) self.setup_log_dir(self.__class__.__name__) @@ -81,6 +87,7 @@ def tearDown(self): # restore saved host behavior support data set_features_cmd = f"{self.nvme_bin} set-feature {self.ctrl} " + \ "--feature-id=0x16 --data-len=512" + logger.debug(set_features_cmd) proc = subprocess.Popen(set_features_cmd, shell=True, stdout=subprocess.PIPE, diff --git a/tests/nvme_format_test.py b/tests/nvme_format_test.py index 7cdd72df94..9c247c842a 100644 --- a/tests/nvme_format_test.py +++ b/tests/nvme_format_test.py @@ -38,11 +38,14 @@ """ import json +import logging import math import subprocess from nvme_test import TestNVMe +logger = logging.getLogger(__name__) + class TestNVMeFormatCmd(TestNVMe): @@ -107,13 +110,16 @@ def attach_detach_primary_ns(self): # read lbaf information id_ns_cmd = f"{self.nvme_bin} id-ns {self.ctrl} " + \ f"--namespace-id={self.default_nsid} --output-format=json" + logger.debug(id_ns_cmd) proc = subprocess.Popen(id_ns_cmd, shell=True, stdout=subprocess.PIPE, encoding='utf-8') err = proc.wait() self.assertEqual(err, 0, "ERROR : nvme id-ns failed") - json_output = json.loads(proc.stdout.read()) + output = proc.stdout.read() + logger.debug(output) + json_output = json.loads(output) self.lba_format_list = json_output['lbafs'] self.assertTrue(len(self.lba_format_list) > 0, "ERROR : nvme id-ns could not find any lba formats") diff --git a/tests/nvme_fw_log_test.py b/tests/nvme_fw_log_test.py index e56953df8b..047579b3df 100644 --- a/tests/nvme_fw_log_test.py +++ b/tests/nvme_fw_log_test.py @@ -26,8 +26,6 @@ 1. Execute fw-log on a device. """ -import subprocess - from nvme_test import TestNVMe @@ -58,11 +56,7 @@ def get_fw_log(self): - 0 on success, error code on failure. """ fw_log_cmd = f"{self.nvme_bin} fw-log {self.ctrl}" - proc = subprocess.Popen(fw_log_cmd, - shell=True, - stdout=subprocess.PIPE, - encoding='utf-8') - return proc.wait() + return self.exec_cmd(fw_log_cmd) def test_fw_log(self): """ Testcase main """ diff --git a/tests/nvme_get_features_test.py b/tests/nvme_get_features_test.py index d1bf6211f7..ff22eb72d0 100644 --- a/tests/nvme_get_features_test.py +++ b/tests/nvme_get_features_test.py @@ -34,10 +34,13 @@ 9. 0Bh M Asynchronous Event Configuration. """ +import logging import subprocess from nvme_test import TestNVMe +logger = logging.getLogger(__name__) + class TestNVMeGetMandatoryFeatures(TestNVMe): @@ -59,11 +62,14 @@ def setUp(self): device = self.ctrl.split('/')[-1] get_vector_list_cmd = "grep " + device + "q /proc/interrupts |" \ " cut -d : -f 1 | tr -d ' ' | tr '\n' ' '" + logger.debug(get_vector_list_cmd) proc = subprocess.Popen(get_vector_list_cmd, shell=True, stdout=subprocess.PIPE, encoding='utf-8') - self.vector_list_len = len(proc.stdout.read().strip().split(" ")) + output = proc.stdout.read() + logger.debug(output) + self.vector_list_len = len(output.strip().split(" ")) def tearDown(self): """ Post Section for TestNVMeGetMandatoryFeatures @@ -84,21 +90,13 @@ def get_mandatory_features(self, feature_id): get_feat_cmd = f"{self.nvme_bin} get-feature {self.ctrl} " + \ f"--feature-id={str(feature_id)} " + \ f"--cdw11={str(vector)} --human-readable" - proc = subprocess.Popen(get_feat_cmd, - shell=True, - stdout=subprocess.PIPE, - encoding='utf-8') - self.assertEqual(proc.wait(), 0) + self.assertEqual(self.exec_cmd(get_feat_cmd), 0) else: get_feat_cmd = f"{self.nvme_bin} get-feature {self.ctrl} " + \ f"--feature-id={str(feature_id)} --human-readable" if str(feature_id) == "0x05": get_feat_cmd += f" --namespace-id={self.default_nsid}" - proc = subprocess.Popen(get_feat_cmd, - shell=True, - stdout=subprocess.PIPE, - encoding='utf-8') - self.assertEqual(proc.wait(), 0) + self.assertEqual(self.exec_cmd(get_feat_cmd), 0) def test_get_mandatory_features(self): """ Testcase main """ diff --git a/tests/nvme_get_lba_status_test.py b/tests/nvme_get_lba_status_test.py index 15842cfba8..68009014ff 100644 --- a/tests/nvme_get_lba_status_test.py +++ b/tests/nvme_get_lba_status_test.py @@ -12,8 +12,6 @@ 1. Execute get-lba-status on a device. """ -import subprocess - from nvme_test import TestNVMe @@ -56,11 +54,7 @@ def get_lba_status(self): f"--max-dw={str(self.max_dw)} " + \ f"--action={str(self.action)} " + \ f"--range-len={str(self.range_len)}" - proc = subprocess.Popen(get_lba_status_cmd, - shell=True, - stdout=subprocess.PIPE, - encoding='utf-8') - return proc.wait() + return self.exec_cmd(get_lba_status_cmd) def test_get_lba_status(self): """ Testcase main """ diff --git a/tests/nvme_id_ns_test.py b/tests/nvme_id_ns_test.py index 46ed3eeffe..30fbd696fc 100644 --- a/tests/nvme_id_ns_test.py +++ b/tests/nvme_id_ns_test.py @@ -27,8 +27,6 @@ 2. Execute id-ns on all namespaces """ -import subprocess - from nvme_test import TestNVMe @@ -62,11 +60,7 @@ def get_id_ns(self, nsid): """ id_ns_cmd = f"{self.nvme_bin} id-ns {self.ctrl} " + \ f"--namespace-id={str(nsid)}" - proc = subprocess.Popen(id_ns_cmd, - shell=True, - stdout=subprocess.PIPE, - encoding='utf-8') - return proc.wait() + return self.exec_cmd(id_ns_cmd) def get_id_ns_all(self): """ diff --git a/tests/nvme_lba_status_log_test.py b/tests/nvme_lba_status_log_test.py index 079fe5c71c..8821cfa09b 100644 --- a/tests/nvme_lba_status_log_test.py +++ b/tests/nvme_lba_status_log_test.py @@ -12,8 +12,6 @@ 1. Execute lba-status-log on a device. """ -import subprocess - from nvme_test import TestNVMe @@ -46,11 +44,7 @@ def get_lba_stat_log(self): - 0 on success, error code on failure. """ lba_stat_log_cmd = f"{self.nvme_bin} lba-status-log {self.ctrl}" - proc = subprocess.Popen(lba_stat_log_cmd, - shell=True, - stdout=subprocess.PIPE, - encoding='utf-8') - return proc.wait() + return self.exec_cmd(lba_stat_log_cmd) def test_lba_stat_log(self): """ Testcase main """ diff --git a/tests/nvme_test.py b/tests/nvme_test.py index 1571329a78..d8a8eb4311 100644 --- a/tests/nvme_test.py +++ b/tests/nvme_test.py @@ -23,6 +23,7 @@ """ import json +import logging import mmap import os import re @@ -35,6 +36,8 @@ from nvme_test_logger import TestNVMeLogger +logger = logging.getLogger(__name__) + def to_decimal(value): """ Wrapper for converting numbers to base 10 decimal @@ -77,7 +80,6 @@ def setUp(self): self.do_validate_pci_device = True self.default_nsid = 0x1 self.flbas = 0 - self.debug = False self.config_file = os.path.join(os.path.dirname(os.path.abspath(__file__)), 'config.json') self.load_config() @@ -86,8 +88,8 @@ def setUp(self): self.ns_mgmt_supported = self.get_ns_mgmt_support() if self.ns_mgmt_supported: self.create_and_attach_default_ns() - if self.debug: - print(f"setup: ctrl: {self.ctrl}, ns1: {self.ns1}, default_nsid: {self.default_nsid}, flbas: {self.flbas}") + logger.debug("setup: ctrl: %s, ns1: %s, default_nsid: %s, flbas: %s", + self.ctrl, self.ns1, self.default_nsid, self.flbas) def tearDown(self): """ Post Section for TestNVMe. """ @@ -132,6 +134,7 @@ def validate_pci_device(self): """ x1, x2, dev = self.ctrl.split('/') cmd = "find /sys/devices -name \\*" + dev + " | grep -i pci" + logger.debug(cmd) err = subprocess.call(cmd, shell=True, stdout=subprocess.DEVNULL) self.assertEqual(err, 0, "ERROR : Only NVMe PCI subsystem is supported") @@ -148,13 +151,18 @@ def load_config(self): self.ns1 = config['ns1'] self.log_dir = config['log_dir'] self.nvme_bin = config.get('nvme_bin', self.nvme_bin) - self.debug = config.get('debug', False) - if self.debug: - print(f"Using nvme binary '{self.nvme_bin}'") self.do_validate_pci_device = config.get( 'do_validate_pci_device', self.do_validate_pci_device) self.clear_log_dir = False + log_level_str = config.get('log_level', + 'DEBUG' if config.get('debug', False) else 'WARNING') + log_level = getattr(logging, log_level_str.upper(), logging.WARNING) + if not logging.getLogger().handlers: + logging.basicConfig(format='%(message)s', stream=sys.stdout) + logging.getLogger().setLevel(log_level) + logger.debug("Using nvme binary '%s'", self.nvme_bin) + if self.clear_log_dir is True: shutil.rmtree(self.log_dir, ignore_errors=True) @@ -176,9 +184,12 @@ def setup_log_dir(self, test_name): def exec_cmd(self, cmd): """ Wrapper for executing a shell command and return the result. """ + logger.debug(cmd) proc = subprocess.Popen(cmd, shell=True, stdout=subprocess.PIPE, encoding='utf-8') - return proc.wait() + ret = proc.wait() + logger.debug(proc.stdout.read()) + return ret def nvme_reset_ctrl(self): """ Wrapper for nvme reset command. @@ -188,11 +199,13 @@ def nvme_reset_ctrl(self): - None """ nvme_reset_cmd = f"{self.nvme_bin} reset {self.ctrl}" + logger.debug(nvme_reset_cmd) err = subprocess.call(nvme_reset_cmd, shell=True, stdout=subprocess.DEVNULL) self.assertEqual(err, 0, "ERROR : nvme reset failed") rescan_cmd = "echo 1 > /sys/bus/pci/rescan" + logger.debug(rescan_cmd) proc = subprocess.Popen(rescan_cmd, shell=True, stdout=subprocess.PIPE, @@ -209,13 +222,16 @@ def get_ctrl_id(self): """ get_ctrl_id = f"{self.nvme_bin} list-ctrl {self.ctrl} " + \ "--output-format=json" + logger.debug(get_ctrl_id) proc = subprocess.Popen(get_ctrl_id, shell=True, stdout=subprocess.PIPE, encoding='utf-8') err = proc.wait() self.assertEqual(err, 0, "ERROR : nvme list-ctrl failed") - json_output = json.loads(proc.stdout.read()) + output = proc.stdout.read() + logger.debug(output) + json_output = json.loads(output) self.assertTrue(len(json_output['ctrl_list']) > 0, "ERROR : nvme list-ctrl could not find ctrl") return str(json_output['ctrl_list'][0]['ctrl_id']) @@ -254,12 +270,15 @@ def get_nsid_list(self): ns_list = [] ns_list_cmd = f"{self.nvme_bin} list-ns {self.ctrl} " + \ "--output-format=json" + logger.debug(ns_list_cmd) proc = subprocess.Popen(ns_list_cmd, shell=True, stdout=subprocess.PIPE, encoding='utf-8') self.assertEqual(proc.wait(), 0, "ERROR : nvme list namespace failed") - json_output = json.loads(proc.stdout.read()) + output = proc.stdout.read() + logger.debug(output) + json_output = json.loads(output) for ns in json_output['nsid_list']: ns_list.append(ns['nsid']) @@ -275,13 +294,16 @@ def get_max_ns(self): """ max_ns_cmd = f"{self.nvme_bin} id-ctrl {self.ctrl} " + \ "--output-format=json" + logger.debug(max_ns_cmd) proc = subprocess.Popen(max_ns_cmd, shell=True, stdout=subprocess.PIPE, encoding='utf-8') err = proc.wait() self.assertEqual(err, 0, "ERROR : reading maximum namespace count failed") - json_output = json.loads(proc.stdout.read()) + output = proc.stdout.read() + logger.debug(output) + json_output = json.loads(output) return int(json_output['nn']) def get_lba_status_supported(self): @@ -302,13 +324,16 @@ def get_lba_format_size(self): """ nvme_id_ns_cmd = f"{self.nvme_bin} id-ns {self.ns1} " + \ "--output-format=json" + logger.debug(nvme_id_ns_cmd) proc = subprocess.Popen(nvme_id_ns_cmd, shell=True, stdout=subprocess.PIPE, encoding='utf-8') err = proc.wait() self.assertEqual(err, 0, "ERROR : reading id-ns") - json_output = json.loads(proc.stdout.read()) + output = proc.stdout.read() + logger.debug(output) + json_output = json.loads(output) self.assertTrue(len(json_output['lbafs']) > self.flbas, "Error : could not match the given flbas to an existing lbaf") lbaf_json = json_output['lbafs'][int(self.flbas)] @@ -340,13 +365,16 @@ def get_id_ctrl_field_value(self, field): """ id_ctrl_cmd = f"{self.nvme_bin} id-ctrl {self.ctrl} " + \ "--output-format=json" + logger.debug(id_ctrl_cmd) proc = subprocess.Popen(id_ctrl_cmd, shell=True, stdout=subprocess.PIPE, encoding='utf-8') err = proc.wait() self.assertEqual(err, 0, "ERROR : reading id-ctrl failed") - json_output = json.loads(proc.stdout.read()) + output = proc.stdout.read() + logger.debug(output) + json_output = json.loads(output) self.assertTrue(field in json_output, f"ERROR : reading field '{field}' failed") return str(json_output[field]) @@ -372,12 +400,15 @@ def delete_all_ns(self): self.assertEqual(self.exec_cmd(delete_ns_cmd), 0) list_ns_cmd = f"{self.nvme_bin} list-ns {self.ctrl} --all " + \ "--output-format=json" + logger.debug(list_ns_cmd) proc = subprocess.Popen(list_ns_cmd, shell=True, stdout=subprocess.PIPE, encoding='utf-8') self.assertEqual(proc.wait(), 0, "ERROR : nvme list-ns failed") - json_output = json.loads(proc.stdout.read()) + output = proc.stdout.read() + logger.debug(output) + json_output = json.loads(output) self.assertEqual(len(json_output['nsid_list']), 0, "ERROR : deleting all namespace failed") @@ -394,6 +425,7 @@ def create_ns(self, nsze, ncap, flbas, dps): create_ns_cmd = f"{self.nvme_bin} create-ns {self.ctrl} " + \ f"--nsze={str(nsze)} --ncap={str(ncap)} --flbas={str(flbas)} " + \ f"--dps={str(dps)} --verbose --output-format=json" + logger.debug(create_ns_cmd) return subprocess.Popen(create_ns_cmd, shell=True, stdout=subprocess.PIPE, encoding='utf-8') @@ -411,11 +443,14 @@ def create_and_validate_ns(self, nsid, nsze, ncap, flbas, dps): proc = self.create_ns(nsze, ncap, flbas, dps) err = proc.wait() if err == 0: - json_output = json.loads(proc.stdout.read()) + output = proc.stdout.read() + logger.debug(output) + json_output = json.loads(output) self.assertEqual(int(json_output['nsid']), nsid, "ERROR : create namespace failed") id_ns_cmd = f"{self.nvme_bin} id-ns {self.ctrl} " + \ f"--namespace-id={str(nsid)}" + logger.debug(id_ns_cmd) err = subprocess.call(id_ns_cmd, shell=True, stdout=subprocess.DEVNULL) @@ -431,6 +466,7 @@ def attach_ns(self, ctrl_id, nsid): """ attach_ns_cmd = f"{self.nvme_bin} attach-ns {self.ctrl} " + \ f"--namespace-id={str(nsid)} --controllers={ctrl_id} --verbose" + logger.debug(attach_ns_cmd) err = subprocess.call(attach_ns_cmd, shell=True, stdout=subprocess.DEVNULL) @@ -457,6 +493,7 @@ def detach_ns(self, ctrl_id, nsid): """ detach_ns_cmd = f"{self.nvme_bin} detach-ns {self.ctrl} " + \ f"--namespace-id={str(nsid)} --controllers={ctrl_id} --verbose" + logger.debug(detach_ns_cmd) return subprocess.call(detach_ns_cmd, shell=True, stdout=subprocess.DEVNULL) @@ -471,6 +508,7 @@ def delete_and_validate_ns(self, nsid): # delete the namespace delete_ns_cmd = f"{self.nvme_bin} delete-ns {self.ctrl} " + \ f"--namespace-id={str(nsid)} --verbose" + logger.debug(delete_ns_cmd) err = subprocess.call(delete_ns_cmd, shell=True, stdout=subprocess.DEVNULL) @@ -486,11 +524,7 @@ def get_smart_log(self, nsid): """ smart_log_cmd = f"{self.nvme_bin} smart-log {self.ctrl} " + \ f"--namespace-id={str(nsid)}" - proc = subprocess.Popen(smart_log_cmd, - shell=True, - stdout=subprocess.PIPE, - encoding='utf-8') - err = proc.wait() + err = self.exec_cmd(smart_log_cmd) self.assertEqual(err, 0, "ERROR : nvme smart log failed") return err @@ -506,11 +540,7 @@ def get_id_ctrl(self, vendor=False): else: id_ctrl_cmd = f"{self.nvme_bin} id-ctrl " +\ f"--vendor-specific {self.ctrl}" - proc = subprocess.Popen(id_ctrl_cmd, - shell=True, - stdout=subprocess.PIPE, - encoding='utf-8') - err = proc.wait() + err = self.exec_cmd(id_ctrl_cmd) self.assertEqual(err, 0, "ERROR : nvme id controller failed") return err @@ -523,19 +553,20 @@ def get_error_log(self): """ pattern = re.compile(r"^ Entry\[[ ]*[0-9]+\]") error_log_cmd = f"{self.nvme_bin} error-log {self.ctrl}" + logger.debug(error_log_cmd) proc = subprocess.Popen(error_log_cmd, shell=True, stdout=subprocess.PIPE, encoding='utf-8') err = proc.wait() self.assertEqual(err, 0, "ERROR : nvme error log failed") - # This sanity checkes the 'normal' output - line = proc.stdout.readline() - err_log_entry_count = int(line.split(" ")[5].strip().split(":")[1]) - entry_count = 0 - for line in proc.stdout: - if pattern.match(line): - entry_count += 1 + output = proc.stdout.read() + logger.debug(output) + lines = output.splitlines() + if not lines: + return 1 + err_log_entry_count = int(lines[0].split(" ")[5].strip().split(":")[1]) + entry_count = sum(1 for line in lines[1:] if pattern.match(line)) return 0 if err_log_entry_count == entry_count else 1 @@ -551,14 +582,14 @@ def run_ns_io(self, nsid, lbads, count=10): ns_path = self.ctrl + "n" + str(nsid) io_cmd = "dd if=" + ns_path + " of=/dev/null" + " bs=" + \ str(block_size) + " count=" + str(count) + " > /dev/null 2>&1" - print(f"Running io: {io_cmd}") + logger.debug(io_cmd) run_io = subprocess.Popen(io_cmd, shell=True, stdout=subprocess.PIPE, encoding='utf-8') run_io_result = run_io.communicate()[1] self.assertEqual(run_io_result, None) io_cmd = "dd if=/dev/zero of=" + ns_path + " bs=" + \ str(block_size) + " count=" + str(count) + " > /dev/null 2>&1" - print(f"Running io: {io_cmd}") + logger.debug(io_cmd) run_io = subprocess.Popen(io_cmd, shell=True, stdout=subprocess.PIPE, encoding='utf-8') run_io_result = run_io.communicate()[1]