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/ha/demo_test.sh

@@ -8,6 +8,10 @@ function cephnvmf_func()
 function demo_test_unsecured()
 {
     make demo OPTS=-T
+    #############################################################################
+    id
+    ls -lR /var/log/ceph
+    #############################################################################
     return $?
 }