Fix log in github action to debug. (#1889)

### What problem does this PR solve?

Copy test log file to a random path if an error occurred.

### Type of change

- [x] Bug Fix (non-breaking change which fixes an issue)

.github/workflows/slow_test.yml

@@ -77,7 +77,8 @@ jobs:
 
       - name: Collect infinity release output
         if: ${{ !cancelled()  && failure() }} # always run this step even if previous steps failed
-        run: (cat release.log 2>/dev/null; cat /var/infinity/log/infinity.log 2>/dev/null) || true
+        run: |
+          sudo python3 scripts/collect_log.py --log_path=/var/infinity/log/infinity.log --stdout_path=release.log --output_dir=${RUNNER_WORKSPACE_PREFIX}/log
 
       - name: Prepare restart test data
         if: ${{ !cancelled() && !failure() }}

.github/workflows/tests.yml

@@ -108,7 +108,8 @@ jobs:
       - name: Collect infinity debug output
         if: ${{ !cancelled() && failure() }}
         # GitHub Actions interprets output lines starting with "Error" as error messages, and it automatically sets the step status to failed when such lines are detected.
-        run: (cat debug.log 2>/dev/null; cat /var/infinity/log/infinity.log 2>/dev/null) || true
+        run: |
+          sudo python3 scripts/collect_log.py --log_path=/var/infinity/log/infinity.log --stdout_path=debug.log --output_dir=${RUNNER_WORKSPACE_PREFIX}/log
 
       - name: Start infinity debug version with vfs off
         if: ${{ !cancelled() && !failure() }}
@@ -134,7 +135,8 @@ jobs:
       - name: Collect infinity debug output
         if: ${{ !cancelled() && failure() }}
         # GitHub Actions interprets output lines starting with "Error" as error messages, and it automatically sets the step status to failed when such lines are detected.
-        run: (cat vfs_debug.log 2>/dev/null; cat /var/infinity/log/infinity.log 2>/dev/null) || true
+        run: |
+          sudo python3 scripts/collect_log.py --log_path=/var/infinity/log/infinity.log --stdout_path=vfs_debug.log --output_dir=${RUNNER_WORKSPACE_PREFIX}/log
 
       - name: Unit test debug version
         if: ${{ !cancelled() && !failure() }}
@@ -247,7 +249,8 @@ jobs:
       - name: Collect infinity release output
         if: ${{ !cancelled() && failure() }} # always run this step even if previous steps failed
         # GitHub Actions interprets output lines starting with "Error" as error messages, and it automatically sets the step status to failed when such lines are detected. 
-        run: (cat release.log 2>/dev/null; cat /var/infinity/log/infinity.log 2>/dev/null) || true
+        run: |
+          sudo python3 scripts/collect_log.py --log_path=/var/infinity/log/infinity.log --stdout_path=release.log --output_dir=${RUNNER_WORKSPACE_PREFIX}/log
 
       - name: Start infinity release version with vfs off
         if: ${{ !cancelled() && !failure() }}
@@ -273,7 +276,8 @@ jobs:
       - name: Collect infinity release output
         if: ${{ !cancelled() && failure() }} # always run this step even if previous steps failed
         # GitHub Actions interprets output lines starting with "Error" as error messages, and it automatically sets the step status to failed when such lines are detected.
-        run: (cat release.log 2>/dev/null; cat /var/infinity/log/infinity.log 2>/dev/null) || true
+        run: |
+          sudo python3 scripts/collect_log.py --log_path=/var/infinity/log/infinity.log --stdout_path=vfs_release.log --output_dir=${RUNNER_WORKSPACE_PREFIX}/log
     
       - name: Unit test release version
         if: ${{ !cancelled() && !failure() }}

conf/pytest_parallel_infinity_conf.toml

@@ -8,6 +8,8 @@ server_address           = "0.0.0.0"
 [log]
 log_filename             = "infinity.log"
 log_dir                  = "/var/infinity/log"
+log_to_stdout            = true
+log_level               = "trace"
 
 [storage]
 persistence_dir          = "/var/infinity/persistence"

conf/pytest_parallel_infinity_vfs_off.toml

@@ -8,6 +8,8 @@ server_address           = "0.0.0.0"
 [log]
 log_filename             = "infinity.log"
 log_dir                  = "/var/infinity/log"
+log_to_stdout            = true
+log_level               = "trace"
 
 [storage]
 data_dir                 = "/var/infinity/data"

scripts/collect_log.py

@@ -0,0 +1,41 @@
+import os
+import shutil
+import random
+import string
+import argparse
+
+parser = argparse.ArgumentParser(description="Collect and copy log files.")
+parser.add_argument(
+    "--log_path", type=str, required=True, help="Path to the infinity log file"
+)
+parser.add_argument(
+    "--stdout_path", type=str, required=True, help="Path to the output debug log file"
+)
+parser.add_argument(
+    "--output_dir",
+    type=str,
+    default="/var/infinity/log",
+    help="Path to the output directory",
+)
+args = parser.parse_args()
+
+log_path = args.log_path
+stdout_path = args.stdout_path
+output_dir = args.output_dir
+
+if not os.path.isdir(output_dir):
+    os.makedirs(output_dir)
+
+
+random_name = "".join(random.choices(string.ascii_lowercase + string.digits, k=8))
+print(f"Random log file name: {random_name}")
+
+if not os.path.isfile(stdout_path):
+    print("Error: stdout file not found")
+else:
+    shutil.copy(stdout_path, f"{output_dir}/{random_name}_.log")
+
+if not os.path.isfile(log_path):
+    print("Error: /var/infinity/log/infinity.log not found")
+else:
+    shutil.copy(log_path, f"{output_dir}/{random_name}.log")

src/main/cluster_manager.cpp

@@ -246,6 +246,7 @@ void ClusterManager::CheckHeartBeatInner() {
             if (node_info->node_status_ == NodeStatus::kAlive) {
                 if (node_info->last_update_ts_ + 2 * leader_node_->heartbeat_interval_ < this_node_->last_update_ts_) {
                     node_info->node_status_ = NodeStatus::kTimeout;
+                    LOG_INFO(fmt::format("Node {} is timeout", node_name));
                 }
             }
         }

src/storage/buffer/file_worker/file_worker.cpp

@@ -106,9 +106,8 @@ bool FileWorker::WriteToFile(bool to_spill, const FileWorkerSaveCtx &ctx) {
 
 void FileWorker::ReadFromFile(bool from_spill) {
     LocalFileSystem fs;
-    String read_path;
     bool use_object_cache = !from_spill && persistence_manager_ != nullptr;
-    read_path = fmt::format("{}/{}", ChooseFileDir(from_spill), *file_name_);
+    String read_path = fmt::format("{}/{}", ChooseFileDir(from_spill), *file_name_);
     if (use_object_cache) {
         obj_addr_ = persistence_manager_->GetObjCache(read_path);
         if (!obj_addr_.Valid()) {
@@ -134,7 +133,7 @@ void FileWorker::ReadFromFile(bool from_spill) {
         file_handler_->Close();
         file_handler_ = nullptr;
         if (use_object_cache && obj_addr_.Valid()) {
-            read_path = fmt::format("{}/{}", ChooseFileDir(from_spill), *file_name_);
+            String read_path = fmt::format("{}/{}", ChooseFileDir(from_spill), *file_name_);
             persistence_manager_->PutObjCache(read_path);
         }
     });

src/storage/meta/entry/base_entry.cpp

@@ -39,6 +39,11 @@ bool BaseEntry::CheckVisible(Txn *txn) const {
         UnrecoverableError(error_message);
     }
     // Check if the entry is in committing process, because commit_ts of the base_entry is set in the Txn::CommitBottom
+    if (txn_id_ == 0) {
+        // could not check if the entry is visible accurately. log a warning and return true
+        LOG_WARN(fmt::format("Entry {} txn id is not set", *encode_));
+        return true;
+    }
     return txn_mgr->CheckIfCommitting(txn_id_, begin_ts);
 }
 

src/storage/persistence/persistence_manager.cpp

@@ -320,7 +320,7 @@ ObjAddr PersistenceManager::GetObjCache(const String &file_path) {
 void PersistenceManager::PutObjCache(const String &file_path) {
     String local_path = RemovePrefix(file_path);
     if (local_path.empty()) {
-        String error_message = fmt::format("Failed to find local path of {}", local_path);
+        String error_message = fmt::format("Failed to find file path of {}", file_path);
         UnrecoverableError(error_message);
     }
 
@@ -330,13 +330,17 @@ void PersistenceManager::PutObjCache(const String &file_path) {
         String error_message = fmt::format("Failed to find file_path: {} stored object", local_path);
         UnrecoverableError(error_message);
     }
-    assert(it->second.part_size_ != 0);
+    if (it->second.part_size_ == 0) {
+        UnrecoverableError(fmt::format("PutObjCache object {} part size is 0", it->second.obj_key_));
+    }
     auto oit = objects_.find(it->second.obj_key_);
     if (oit == objects_.end()) {
         return;
     }
 
-    assert(oit->second.ref_count_ > 0);
+    if (oit->second.ref_count_ <= 0) {
+        UnrecoverableError(fmt::format("PutObjCache object {} ref count is {}", it->second.obj_key_, oit->second.ref_count_));
+    }
     oit->second.ref_count_--;
 }
 

test/data/config/restart_test/test_memidx/1.toml

@@ -5,6 +5,7 @@ time_zone = "utc-8"
 [network]
 [log]
 log_to_stdout = true
+log_level = "trace"
 
 [storage]
 optimize_interval = "0s"

test/data/config/restart_test/test_memidx/2.toml

@@ -5,6 +5,7 @@ time_zone = "utc-8"
 [network]
 [log]
 log_to_stdout = true
+log_level = "trace"
 
 [storage]
 optimize_interval = "0s"

test/data/config/restart_test/test_memidx/3.toml

@@ -5,6 +5,7 @@ time_zone = "utc-8"
 [network]
 [log]
 log_to_stdout = true
+log_level = "trace"
 
 [storage]
 optimize_interval = "1s"