Add logging to tests

.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

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;

tests/config.json

@@ -1,5 +1,6 @@
 {
 	"controller" : "/dev/nvme0",
         "ns1": "/dev/nvme0n1",
-	"log_dir": "nvmetests/"
+	"log_dir": "nvmetests",
+	"log_level": "DEBUG"
 }

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,13 +69,15 @@ 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,
                                 encoding='utf-8')
         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,

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")

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 """

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 """

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 """

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):
         """

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 """