Allow saving SPDK output to a file.

Fixes ceph#906

Signed-off-by: Gil Bregman <[email protected]>

ceph-nvmeof.conf

@@ -68,6 +68,7 @@ tgt_path = /usr/local/bin/nvmf_tgt
 timeout = 60.0
 #log_level =
 #protocol_log_level = WARNING
+log_file_dir = /var/log/ceph
 
 # Example value: -m 0x3 -L all
 # tgt_cmd_extra_args =

control/server.py

@@ -92,6 +92,8 @@ def __init__(self, config: GatewayConfig):
         self.gw_logger_object = GatewayLogger(self.config)
         self.logger = self.gw_logger_object.logger
         self.spdk_process = None
+        self.spdk_log_file = None
+        self.spdk_log_file_path = None
         self.gateway_rpc = None
         self.server = None
         self.discovery_pid = None
@@ -130,6 +132,17 @@ def __exit__(self, exc_type, exc_value, traceback):
         if self.spdk_process:
             self._stop_spdk()
 
+        if self.spdk_log_file:
+            try:
+                close(self.spdk_log_file)
+            except Exception:
+                pass
+            self.spdk_log_file = None
+
+        if self.spdk_log_file_path:
+            GatewayLogger.compress_file(self.spdk_log_file_path, f"{self.spdk_log_file_path}.gz")
+            self.spdk_log_file_path = None
+
         if self.server:
             if logger:
                 logger.info("Stopping the server...")
@@ -403,11 +416,45 @@ def _start_spdk(self, omap_state):
             self.logger.info(f"SPDK autodetecting cpu_mask: {cpu_mask}")
             cmd += shlex.split(cpu_mask)
 
+        self.spdk_log_file = None
+        self.spdk_log_file_path = None
+        log_stderr = None
+        log_file_dir = self.config.get_with_default("spdk", "log_file_dir", None)
+        if log_file_dir and log_file_dir.strip():
+            log_file_dir = log_file_dir.strip()
+            try:
+                os.makedirs(log_file_dir, 0o755, True)
+            except Exception:
+                pass
+            if not log_file_dir.endswith("/"):
+                log_file_dir += "/"
+            self.spdk_log_file_path = f"{log_file_dir}spdk_{self.name}.log"
+            try:
+                os.remove(f"{self.spdk_log_file_path}.bak")
+            except Exception:
+                pass
+            try:
+                os.remove(f"{self.spdk_log_file_path}.gz.bak")
+            except Exception:
+                pass
+            try:
+                os.rename(self.spdk_log_file_path, f"{self.spdk_log_file_path}.bak")
+            except Exception:
+                pass
+            try:
+                os.rename(f"{log_file_path}.gz", f"{self.spdk_log_file_path}.gz.bak")
+            except Exception:
+                pass
+            try:
+                self.spdk_log_file = open(self.spdk_log_file_path, "wt")
+                log_stderr = subprocess.STDOUT
+            except Exception:
+                pass
         self.logger.info(f"Starting {' '.join(cmd)}")
         try:
             # start spdk process
             time.sleep(2)      # this is a temporary hack, we have a timing issue here. Once we solve it the sleep will ve removed
-            self.spdk_process = subprocess.Popen(cmd)
+            self.spdk_process = subprocess.Popen(cmd, stdout=self.spdk_log_file, stderr=log_stderr)
         except Exception:
             self.logger.exception(f"Unable to start SPDK")
             raise
@@ -424,6 +471,8 @@ def _start_spdk(self, omap_state):
         # connect timeout: spdk client retries 5 times per sec
         conn_retries = int(timeout * 5)
         self.logger.info(f"SPDK process id: {self.spdk_process.pid}")
+        if self.spdk_log_file and self.spdk_log_file_path:
+            self.logger.info(f"SPDK log file is {self.spdk_log_file_path}")
         self.logger.info(
             f"Attempting to initialize SPDK: rpc_socket: {self.spdk_rpc_socket_path},"
             f" conn_retries: {conn_retries}, timeout: {timeout}, log level: {protocol_log_level}"
@@ -504,6 +553,15 @@ def _stop_spdk(self):
         timeout = self.config.getfloat_with_default("spdk", "timeout", 60.0)
         self._stop_subprocess(self.spdk_process, timeout)
         self.spdk_process = None
+        if self.spdk_log_file:
+            try:
+                close(self.spdk_log_file)
+            except Exception:
+                pass
+            self.spdk_log_file = None
+        if self.spdk_log_file_path:
+            GatewayLogger.compress_file(self.spdk_log_file_path, f"{self.spdk_log_file_path}.gz")
+            self.spdk_log_file_path = None
 
         # Clean spdk rpc socket
         if self.spdk_rpc_socket_path and os.path.exists(self.spdk_rpc_socket_path):

control/utils.py

@@ -244,7 +244,7 @@ def __init__(self, config=None):
                 max_log_file_size = 0
                 max_log_files_count = 0
             try:
-                os.makedirs(self.log_directory, 0o777, True)
+                os.makedirs(self.log_directory, 0o755, True)
                 logdir_ok = True
                 self.handler = logging.handlers.RotatingFileHandler(self.log_directory + "/" + GatewayLogger.NVME_LOG_FILE_NAME,
                                                  maxBytes = max_log_file_size * 1024 * 1024,

tests/ceph-nvmeof.tls.conf

@@ -28,6 +28,8 @@ enable_spdk_discovery_controller = False
 #verify_nqns = True
 #allowed_consecutive_spdk_ping_failures = 1
 #spdk_ping_interval_in_seconds = 2.0
+#max_hosts_per_namespace = 1
+#max_namespaces_with_netmask = 1000
 
 [gateway-logs]
 log_level=debug
@@ -63,7 +65,9 @@ tgt_path = /usr/local/bin/nvmf_tgt
 #rpc_socket_name = spdk.sock
 #tgt_cmd_extra_args = --env-context="--no-huge -m1024" --iova-mode=va
 timeout = 60.0
-#log_level = WARNING
+#log_level =
+#protocol_log_level = WARNING
+#log_file_dir = /var/log/ceph
 
 # Example value: -m 0x3 -L all
 # tgt_cmd_extra_args =

tests/test_log_files.py

@@ -10,21 +10,21 @@
 import shutil
 import stat
 import gzip
+import glob
 
 config = "ceph-nvmeof.conf"
 subsystem_prefix = "nqn.2016-06.io.spdk:cnode"
 
 def clear_log_files():
-    files = os.listdir("/var/log/ceph")
+    files = glob.glob("/var/log/ceph/nvme*")
     for f in files:
-        fpath = "/var/log/ceph/" + f
-        statinfo = os.stat(fpath)
+        statinfo = os.stat(f)
         if stat.S_ISDIR(statinfo.st_mode):
-            print(f"Deleting directory {fpath}")
-            shutil.rmtree(fpath, ignore_errors = True)
+            print(f"Deleting directory {f}")
+            shutil.rmtree(f, ignore_errors = True)
         else:
-            print(f"Deleting file {fpath}")
-            os.remove(fpath)
+            print(f"Deleting file {f}")
+            os.remove(f)
 
 @pytest.fixture(scope="function")
 def gateway(config, request):
@@ -82,20 +82,20 @@ def test_log_files_disabled(gateway):
     assert subs_list.status == 0
     assert len(subs_list.subsystems) == 1
     assert subs_list.subsystems[0].nqn == subsystem_prefix + "1"
-    files = os.listdir("/var/log/ceph")
+    files = glob.glob("/var/log/ceph/nvme*")
     assert files == []
 
 def test_log_files_rotation(gateway):
     gw = gateway
-    files = os.listdir("/var/log/ceph")
+    files = glob.glob("/var/log/ceph/nvme*")
     assert len(files) == 1
     assert files[0] == f"nvmeof-{gw.name}"
     cli(["subsystem", "add", "--subsystem", subsystem_prefix + "2"])
     cli(["subsystem", "add", "--subsystem", subsystem_prefix + "3"])
     cli(["subsystem", "add", "--subsystem", subsystem_prefix + "4"])
     for i in range(2000):
         cli(["subsystem", "list"])
-    files = os.listdir("/var/log/ceph")
+    files = glob.glob("/var/log/ceph/nvme*")
     assert len(files) == 1
     assert files[0] == f"nvmeof-{gw.name}"
     files = os.listdir(f"/var/log/ceph/nvmeof-{gw.name}")
@@ -119,17 +119,17 @@ def test_log_files_rotation(gateway):
 
 def test_log_files_disable_rotation(gateway):
     gw = gateway
-    files = os.listdir("/var/log/ceph")
+    files = glob.glob("/var/log/ceph/nvme*")
     assert len(files) == 1
-    assert files[0] == f"nvmeof-{gw.name}"
+    assert f"nvmeof-{gw.name}" in files[0]
     cli(["subsystem", "add", "--subsystem", subsystem_prefix + "5"])
     cli(["subsystem", "add", "--subsystem", subsystem_prefix + "6"])
     cli(["subsystem", "add", "--subsystem", subsystem_prefix + "7"])
     for i in range(2000):
         cli(["subsystem", "list"])
-    files = os.listdir("/var/log/ceph")
+    files = glob.glob("/var/log/ceph/nvme*")
     assert len(files) == 1
-    assert files[0] == f"nvmeof-{gw.name}"
+    assert f"nvmeof-{gw.name}" in files[0]
     files = os.listdir(f"/var/log/ceph/nvmeof-{gw.name}")
     assert len(files) == 1
     assert files[0] == "nvmeof-log"