From 4323524a247c483160cfe840d87d3445ed93cdba Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 8 Apr 2026 17:51:43 +0000 Subject: [PATCH 1/5] tests: replace open-coded subprocess calls with self.exec_cmd() Agent-Logs-Url: https://github.com/igaw/nvme-cli/sessions/e04bbed5-abd3-4063-9872-24152bf5cc08 Co-authored-by: igaw <1050803+igaw@users.noreply.github.com> --- tests/nvme_test.py | 29 +++++++---------------------- 1 file changed, 7 insertions(+), 22 deletions(-) diff --git a/tests/nvme_test.py b/tests/nvme_test.py index 1571329a78..b63b5d4726 100644 --- a/tests/nvme_test.py +++ b/tests/nvme_test.py @@ -132,7 +132,7 @@ def validate_pci_device(self): """ x1, x2, dev = self.ctrl.split('/') cmd = "find /sys/devices -name \\*" + dev + " | grep -i pci" - err = subprocess.call(cmd, shell=True, stdout=subprocess.DEVNULL) + err = self.exec_cmd(cmd) self.assertEqual(err, 0, "ERROR : Only NVMe PCI subsystem is supported") def load_config(self): @@ -188,17 +188,10 @@ def nvme_reset_ctrl(self): - None """ nvme_reset_cmd = f"{self.nvme_bin} reset {self.ctrl}" - err = subprocess.call(nvme_reset_cmd, - shell=True, - stdout=subprocess.DEVNULL) + err = self.exec_cmd(nvme_reset_cmd) self.assertEqual(err, 0, "ERROR : nvme reset failed") rescan_cmd = "echo 1 > /sys/bus/pci/rescan" - proc = subprocess.Popen(rescan_cmd, - shell=True, - stdout=subprocess.PIPE, - stderr=subprocess.PIPE, - encoding='utf-8') - self.assertEqual(proc.wait(), 0, "ERROR : pci rescan failed") + self.assertEqual(self.exec_cmd(rescan_cmd), 0, "ERROR : pci rescan failed") def get_ctrl_id(self): """ Wrapper for extracting the first controller id. @@ -416,9 +409,7 @@ def create_and_validate_ns(self, nsid, nsze, ncap, flbas, dps): "ERROR : create namespace failed") id_ns_cmd = f"{self.nvme_bin} id-ns {self.ctrl} " + \ f"--namespace-id={str(nsid)}" - err = subprocess.call(id_ns_cmd, - shell=True, - stdout=subprocess.DEVNULL) + err = self.exec_cmd(id_ns_cmd) return err def attach_ns(self, ctrl_id, nsid): @@ -431,9 +422,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" - err = subprocess.call(attach_ns_cmd, - shell=True, - stdout=subprocess.DEVNULL) + err = self.exec_cmd(attach_ns_cmd) if err != 0: return err @@ -457,9 +446,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" - return subprocess.call(detach_ns_cmd, - shell=True, - stdout=subprocess.DEVNULL) + return self.exec_cmd(detach_ns_cmd) def delete_and_validate_ns(self, nsid): """ Wrapper for deleting and validating that namespace is deleted. @@ -471,9 +458,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" - err = subprocess.call(delete_ns_cmd, - shell=True, - stdout=subprocess.DEVNULL) + err = self.exec_cmd(delete_ns_cmd) self.assertEqual(err, 0, "ERROR : delete namespace failed") return err From 3d47aea983223e81391e71fbf75e0b24a1baff0a Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 8 Apr 2026 18:00:42 +0000 Subject: [PATCH 2/5] tests: replace open-coded Popen+wait patterns with self.exec_cmd() Agent-Logs-Url: https://github.com/igaw/nvme-cli/sessions/c94edfc8-a4da-40d2-a47c-892dd4a6e765 Co-authored-by: igaw <1050803+igaw@users.noreply.github.com> --- tests/nvme_fw_log_test.py | 8 +----- tests/nvme_get_features_test.py | 12 ++------- tests/nvme_get_lba_status_test.py | 8 +----- tests/nvme_id_ns_test.py | 8 +----- tests/nvme_lba_status_log_test.py | 8 +----- tests/nvme_test.py | 41 ++++++++++++++++++------------- 6 files changed, 30 insertions(+), 55 deletions(-) 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..2900cb75d2 100644 --- a/tests/nvme_get_features_test.py +++ b/tests/nvme_get_features_test.py @@ -84,21 +84,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 b63b5d4726..4776737a92 100644 --- a/tests/nvme_test.py +++ b/tests/nvme_test.py @@ -132,7 +132,7 @@ def validate_pci_device(self): """ x1, x2, dev = self.ctrl.split('/') cmd = "find /sys/devices -name \\*" + dev + " | grep -i pci" - err = self.exec_cmd(cmd) + err = subprocess.call(cmd, shell=True, stdout=subprocess.DEVNULL) self.assertEqual(err, 0, "ERROR : Only NVMe PCI subsystem is supported") def load_config(self): @@ -188,10 +188,17 @@ def nvme_reset_ctrl(self): - None """ nvme_reset_cmd = f"{self.nvme_bin} reset {self.ctrl}" - err = self.exec_cmd(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" - self.assertEqual(self.exec_cmd(rescan_cmd), 0, "ERROR : pci rescan failed") + proc = subprocess.Popen(rescan_cmd, + shell=True, + stdout=subprocess.PIPE, + stderr=subprocess.PIPE, + encoding='utf-8') + self.assertEqual(proc.wait(), 0, "ERROR : pci rescan failed") def get_ctrl_id(self): """ Wrapper for extracting the first controller id. @@ -409,7 +416,9 @@ def create_and_validate_ns(self, nsid, nsze, ncap, flbas, dps): "ERROR : create namespace failed") id_ns_cmd = f"{self.nvme_bin} id-ns {self.ctrl} " + \ f"--namespace-id={str(nsid)}" - err = self.exec_cmd(id_ns_cmd) + err = subprocess.call(id_ns_cmd, + shell=True, + stdout=subprocess.DEVNULL) return err def attach_ns(self, ctrl_id, nsid): @@ -422,7 +431,9 @@ 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" - err = self.exec_cmd(attach_ns_cmd) + err = subprocess.call(attach_ns_cmd, + shell=True, + stdout=subprocess.DEVNULL) if err != 0: return err @@ -446,7 +457,9 @@ 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" - return self.exec_cmd(detach_ns_cmd) + return subprocess.call(detach_ns_cmd, + shell=True, + stdout=subprocess.DEVNULL) def delete_and_validate_ns(self, nsid): """ Wrapper for deleting and validating that namespace is deleted. @@ -458,7 +471,9 @@ 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" - err = self.exec_cmd(delete_ns_cmd) + err = subprocess.call(delete_ns_cmd, + shell=True, + stdout=subprocess.DEVNULL) self.assertEqual(err, 0, "ERROR : delete namespace failed") return err @@ -471,11 +486,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 @@ -491,11 +502,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 From 6ae664de6c9256f53db85a38b1b8fb49d631eb97 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Thu, 9 Apr 2026 07:38:15 +0000 Subject: [PATCH 3/5] tests: add logging framework for subprocess command tracing Agent-Logs-Url: https://github.com/igaw/nvme-cli/sessions/c8ec7223-bccb-4a4c-8830-033ea36fa26c Co-authored-by: igaw <1050803+igaw@users.noreply.github.com> --- tests/config.json | 3 ++- tests/nvme_copy_test.py | 9 +++++++- tests/nvme_format_test.py | 4 ++++ tests/nvme_get_features_test.py | 4 ++++ tests/nvme_test.py | 38 ++++++++++++++++++++++++++------- 5 files changed, 48 insertions(+), 10 deletions(-) diff --git a/tests/config.json b/tests/config.json index 098fba807f..27214e3e8f 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": "WARNING" } diff --git a/tests/nvme_copy_test.py b/tests/nvme_copy_test.py index f73cd04b1e..feb637dd84 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, @@ -51,12 +55,13 @@ def setUp(self): # enable cross-namespace copy formats if self.host_behavior_data[4] & cross_namespace_copy: # skip if already enabled - print("Cross-namespace copy already enabled, skipping set-features") + logger.debug("Cross-namespace copy already enabled, skipping set-features") self.host_behavior_data = None else: data = self.host_behavior_data[:4] + cross_namespace_copy.to_bytes(2, 'little') + self.host_behavior_data[6:] set_features_cmd = f"{self.nvme_bin} set-feature " + \ f"{self.ctrl} --feature-id=0x16 --data-len=512" + logger.debug(set_features_cmd) proc = subprocess.Popen(set_features_cmd, shell=True, stdout=subprocess.PIPE, @@ -65,6 +70,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, @@ -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..bd77646518 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,6 +110,7 @@ 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, diff --git a/tests/nvme_get_features_test.py b/tests/nvme_get_features_test.py index 2900cb75d2..440d17723d 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,6 +62,7 @@ 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, diff --git a/tests/nvme_test.py b/tests/nvme_test.py index 4776737a92..a689695204 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,17 @@ 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) + logging.basicConfig(format='# %(message)s') + 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,6 +183,7 @@ 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() @@ -188,11 +196,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,6 +219,7 @@ 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, @@ -254,6 +265,7 @@ 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, @@ -275,6 +287,7 @@ 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, @@ -302,6 +315,7 @@ 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, @@ -340,6 +354,7 @@ 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, @@ -372,6 +387,7 @@ 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, @@ -394,6 +410,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') @@ -416,6 +433,7 @@ def create_and_validate_ns(self, nsid, nsze, ncap, flbas, dps): "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 +449,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 +476,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 +491,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) @@ -515,6 +536,7 @@ 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, @@ -543,14 +565,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] From 17d3c72dcbddb426aba2c622c649867a2b8bacdc Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Thu, 9 Apr 2026 07:44:48 +0000 Subject: [PATCH 4/5] tests: log subprocess stdout output via logger.debug() Agent-Logs-Url: https://github.com/igaw/nvme-cli/sessions/c8ec7223-bccb-4a4c-8830-033ea36fa26c Co-authored-by: igaw <1050803+igaw@users.noreply.github.com> --- tests/nvme_copy_test.py | 2 ++ tests/nvme_format_test.py | 4 +++- tests/nvme_get_features_test.py | 4 +++- tests/nvme_test.py | 40 +++++++++++++++++++++------------ 4 files changed, 34 insertions(+), 16 deletions(-) diff --git a/tests/nvme_copy_test.py b/tests/nvme_copy_test.py index feb637dd84..7d9e514346 100644 --- a/tests/nvme_copy_test.py +++ b/tests/nvme_copy_test.py @@ -52,6 +52,7 @@ def setUp(self): err = proc.wait() self.assertEqual(err, 0, "ERROR : nvme get-feature failed") self.host_behavior_data = proc.stdout.read() + logger.debug(self.host_behavior_data) # enable cross-namespace copy formats if self.host_behavior_data[4] & cross_namespace_copy: # skip if already enabled @@ -78,6 +79,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__) diff --git a/tests/nvme_format_test.py b/tests/nvme_format_test.py index bd77646518..9c247c842a 100644 --- a/tests/nvme_format_test.py +++ b/tests/nvme_format_test.py @@ -117,7 +117,9 @@ def attach_detach_primary_ns(self): 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_get_features_test.py b/tests/nvme_get_features_test.py index 440d17723d..ff22eb72d0 100644 --- a/tests/nvme_get_features_test.py +++ b/tests/nvme_get_features_test.py @@ -67,7 +67,9 @@ def setUp(self): 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 diff --git a/tests/nvme_test.py b/tests/nvme_test.py index a689695204..b1cd4be36c 100644 --- a/tests/nvme_test.py +++ b/tests/nvme_test.py @@ -226,7 +226,9 @@ def get_ctrl_id(self): 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']) @@ -271,7 +273,9 @@ def get_nsid_list(self): 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']) @@ -294,7 +298,9 @@ def get_max_ns(self): 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): @@ -322,7 +328,9 @@ def get_lba_format_size(self): 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)] @@ -361,7 +369,9 @@ def get_id_ctrl_field_value(self, field): 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]) @@ -393,7 +403,9 @@ def delete_all_ns(self): 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") @@ -428,7 +440,9 @@ 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} " + \ @@ -543,13 +557,11 @@ def get_error_log(self): 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() + 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 From 79e0207b0636c4375f6808d41dc889f48ff29a3b Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Thu, 9 Apr 2026 07:47:52 +0000 Subject: [PATCH 5/5] tests: guard basicConfig and empty output in get_error_log Agent-Logs-Url: https://github.com/igaw/nvme-cli/sessions/c8ec7223-bccb-4a4c-8830-033ea36fa26c Co-authored-by: igaw <1050803+igaw@users.noreply.github.com> --- tests/nvme_test.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/tests/nvme_test.py b/tests/nvme_test.py index b1cd4be36c..3f21c23c2c 100644 --- a/tests/nvme_test.py +++ b/tests/nvme_test.py @@ -158,7 +158,8 @@ def load_config(self): 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) - logging.basicConfig(format='# %(message)s') + if not logging.getLogger().handlers: + logging.basicConfig(format='# %(message)s') logging.getLogger().setLevel(log_level) logger.debug("Using nvme binary '%s'", self.nvme_bin) @@ -560,6 +561,8 @@ def get_error_log(self): 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))