Add injected error log ring buffer for fault injection diagnostics (facebook#14431)

Summary:
Add a circular ring buffer (InjectedErrorLog) to FaultInjectionTestFS that records the last 1000 injected errors. Each entry captures the timestamp, thread ID, FS API name with all arguments (file path, offset, buffer size, first 8 bytes of data in hex), and the injected error status. For example:

  Append("/path/035354.sst", size=4096, head=[1a 2b 3c ...]) -> IOError (Retryable): injected write error
  RenameFile("/path/tmp.sst", "/path/035355.sst") -> IOError: injected metadata write error
  Read(offset=16384, size=4096) -> IOError (Retryable): injected read error

The ring buffer is printed to a file automatically:
- On any fatal signal (SIGABRT, SIGSEGV, SIGTERM, SIGINT, SIGHUP, SIGFPE, SIGBUS, SIGILL, SIGQUIT, SIGXCPU, SIGXFSZ, SIGSYS) via a registered crash callback
- At the end of db_stress main(), for diagnostic visibility even when the test completes normally

This addresses a key debugging gap: when write fault injection causes secondary failures (e.g., the builder error propagation issue in T257612259), the injected errors were previously completely silent with no logging trail. The ring buffer provides the missing diagnostic context to correlate fault injection with downstream failures.

Changes:
- port/stack_trace.h/.cc: Add RegisterCrashCallback() API; extend InstallStackTraceHandler() to catch all catchable termination signals
- utilities/fault_injection_fs.h: Add InjectedErrorLog class with printf-style Record(), HexHead() for data bytes, and signal-safe PrintAll()
- utilities/fault_injection_fs.cc: Record full API arguments and error status at all 31 fault injection call sites
- db_stress_tool/db_stress_tool.cc: Register crash callback and print ring buffer at end of main()

Pull Request resolved: facebook#14431

Reviewed By: hx235

Differential Revision: D95435430

Pulled By: xingbowang

fbshipit-source-id: 6c18e1b072044575d6c8c3f198070127b0f80608

Author: xingbowang

db_stress_tool/db_stress_tool.cc

@@ -24,6 +24,7 @@
 #include "db_stress_tool/db_stress_common.h"
 #include "db_stress_tool/db_stress_driver.h"
 #include "db_stress_tool/db_stress_shared_state.h"
+#include "port/stack_trace.h"
 #include "rocksdb/convenience.h"
 #include "utilities/fault_injection_fs.h"
 
@@ -92,6 +93,15 @@ int db_stress_tool(int argc, char** argv) {
     fault_env_guard =
         std::make_shared<CompositeEnvWrapper>(raw_env, fault_fs_guard);
     raw_env = fault_env_guard.get();
+
+    // Register a crash callback so that recently injected errors are
+    // printed to stderr when the process crashes (SIGABRT, SIGSEGV, etc.).
+    // This helps diagnose stress test failures caused by fault injection.
+    port::RegisterCrashCallback([]() {
+      if (fault_fs_guard) {
+        fault_fs_guard->PrintRecentInjectedErrors();
+      }
+    });
   }
 
   auto db_stress_fs =
@@ -301,6 +311,25 @@ int db_stress_tool(int argc, char** argv) {
     FLAGS_db = default_db_path;
   }
 
+  // Now that FLAGS_db is resolved, set the fault injection log file path
+  // so that PrintAll() writes to a file instead of stderr (signal-safe).
+  // Store the log in TEST_TMPDIR (outside the DB directory) so it survives
+  // DB reopen (which cleans untracked files) and gets included in the
+  // sandcastle db.tar.gz artifact for post-failure analysis.
+  if (fault_fs_guard) {
+    std::string log_dir;
+    const char* test_tmpdir = getenv("TEST_TMPDIR");
+    if (test_tmpdir && test_tmpdir[0] != '\0') {
+      log_dir = test_tmpdir;
+    } else {
+      log_dir = "/tmp";
+    }
+    std::string log_path = log_dir + "/fault_injection_" +
+                           std::to_string(getpid()) + "_" +
+                           std::to_string(time(nullptr)) + ".log";
+    fault_fs_guard->SetInjectedErrorLogPath(log_path);
+  }
+
   if ((FLAGS_test_secondary || FLAGS_continuous_verification_interval > 0) &&
       FLAGS_secondaries_base.empty()) {
     std::string default_secondaries_path;

port/stack_trace.cc

@@ -18,6 +18,7 @@ void PrintAndFreeStack(void* /*callstack*/, int /*num_frames*/) {}
 void* SaveStack(int* /*num_frames*/, int /*first_frames_to_skip*/) {
   return nullptr;
 }
+void RegisterCrashCallback(CrashCallback /*callback*/) {}
 }  // namespace port
 }  // namespace ROCKSDB_NAMESPACE
 
@@ -320,6 +321,7 @@ void* SaveStack(int* num_frames, int first_frames_to_skip) {
 static std::atomic<uint64_t> g_thread_handling_stack_trace{0};
 static int g_recursion_count = 0;
 static std::atomic<bool> g_at_exit_called{false};
+static std::atomic<CrashCallback> g_crash_callback{nullptr};
 
 static void StackTraceHandler(int sig) {
   fprintf(stderr, "Received signal %d (%s)\n", sig, strsignal(sig));
@@ -360,6 +362,12 @@ static void StackTraceHandler(int sig) {
       fprintf(stderr, "In a race with process already exiting...\n");
     }
 
+    // Invoke registered crash callback before printing stack trace
+    auto callback = g_crash_callback.load(std::memory_order_acquire);
+    if (callback) {
+      callback();
+    }
+
     // skip the top three signal handler related frames
     PrintStack(3);
 
@@ -398,13 +406,41 @@ static void AtExit() {
   g_at_exit_called.store(true, std::memory_order_release);
 }
 
+// Lightweight handler for graceful termination signals (SIGTERM, SIGINT).
+// Prints the crash callback (e.g., ring buffer) but skips the
+// expensive GDB/LLDB stack trace, since these are intentional terminations.
+static void TerminationHandler(int sig) {
+  char buf[64];
+  int len = snprintf(buf, sizeof(buf), "Received signal %d (%s)\n", sig,
+                     strsignal(sig));
+  if (len > 0) {
+    auto unused __attribute__((unused)) = write(STDOUT_FILENO, buf, len);
+  }
+  auto callback = g_crash_callback.load(std::memory_order_acquire);
+  if (callback) {
+    callback();
+  }
+  signal(sig, SIG_DFL);
+  raise(sig);
+}
+
+void RegisterCrashCallback(CrashCallback callback) {
+  g_crash_callback.store(callback, std::memory_order_release);
+}
+
 void InstallStackTraceHandler() {
   // just use the plain old signal as it's simple and sufficient
   // for this use case
+  // Crash signals — invoke full stack trace + ring buffer
   signal(SIGILL, StackTraceHandler);
   signal(SIGSEGV, StackTraceHandler);
   signal(SIGBUS, StackTraceHandler);
   signal(SIGABRT, StackTraceHandler);
+  signal(SIGFPE, StackTraceHandler);
+  signal(SIGQUIT, StackTraceHandler);
+  // Termination signals — print ring buffer only, no stack trace
+  signal(SIGTERM, TerminationHandler);
+  signal(SIGINT, TerminationHandler);
   atexit(AtExit);
   // Allow ouside debugger to attach, even with Yama security restrictions.
   // This is needed even outside of PrintStack() so that external mechanisms

port/stack_trace.h

@@ -27,5 +27,14 @@ void PrintAndFreeStack(void* callstack, int num_frames);
 // Save the current callstack
 void* SaveStack(int* num_frame, int first_frames_to_skip = 0);
 
+// Register a callback to be invoked when a fatal signal is received,
+// before the stack trace is printed. This is useful for printing diagnostic
+// information (e.g., recently injected errors) when a crash occurs.
+// The callback must only call async-signal-safe functions (write, snprintf,
+// etc.) or functions that are safe enough in practice (fprintf to stderr).
+// Only one callback is supported; subsequent calls overwrite the previous one.
+using CrashCallback = void (*)();
+void RegisterCrashCallback(CrashCallback callback);
+
 }  // namespace port
 }  // namespace ROCKSDB_NAMESPACE

tools/db_crashtest.py

@@ -2,6 +2,7 @@
 # Copyright (c) Facebook, Inc. and its affiliates. All Rights Reserved.
 
 import argparse
+import glob
 import math
 import os
 import random
@@ -1418,11 +1419,16 @@ def execute_cmd(cmd, timeout=None, timeout_pstack=False):
         hit_timeout = True
         if timeout_pstack:
             os.system("pstack %d" % pid)
-        child.kill()
-        print("KILLED %d\n" % child.pid)
-        outs, errs = child.communicate()
+        child.terminate()  # SIGTERM — triggers TerminationHandler
+        try:
+            outs, errs = child.communicate(timeout=3)
+            print("TERMINATED %d\n" % child.pid)
+        except subprocess.TimeoutExpired:
+            child.kill()
+            print("KILLED %d (SIGTERM did not work)\n" % child.pid)
+            outs, errs = child.communicate()
 
-    return hit_timeout, child.returncode, outs.decode("utf-8"), errs.decode("utf-8")
+    return hit_timeout, child.returncode, outs.decode("utf-8"), errs.decode("utf-8"), pid
 
 
 def print_output_and_exit_on_error(stdout, stderr, print_stderr_separately=False):
@@ -1453,6 +1459,54 @@ def cleanup_after_success(dbname):
         sys.exit(2)
 
 
+def print_and_cleanup_fault_injection_log(pid):
+    # Fault injection logs are stored in TEST_TMPDIR (or /tmp) to survive
+    # DB reopen cleanup, and to be included in sandcastle's db.tar.gz artifact.
+    # Filter by pid to only print the log from the current run.
+    max_tail_entries = 32
+    log_dir = os.environ.get(_TEST_DIR_ENV_VAR) or "/tmp"
+    pattern = os.path.join(log_dir, "fault_injection_%d_*.log" % pid)
+    for log in glob.glob(pattern):
+        print("=== Fault injection log: %s ===" % log)
+        try:
+            with open(log) as f:
+                lines = f.readlines()
+            # Log format: header line(s), entry lines, footer line.
+            # The footer starts with "=== End of".
+            # Print header and footer always, truncate entries in the middle.
+            header = []
+            footer = []
+            entries = []
+            for line in lines:
+                stripped = line.strip()
+                if stripped.startswith("=== End of"):
+                    footer.append(line)
+                elif stripped.startswith("===") or stripped == "(none)":
+                    header.append(line)
+                else:
+                    entries.append(line)
+            total_entries = len(entries)
+            print("".join(header), end="")
+            if total_entries <= max_tail_entries:
+                print("".join(entries), end="")
+                print("".join(footer), end="")
+            else:
+                skipped = total_entries - max_tail_entries
+                print(
+                    "... (%d entries omitted, showing last %d. "
+                    "Full log: %s)\n" % (skipped, max_tail_entries, log),
+                    end="",
+                )
+                print("".join(entries[-max_tail_entries:]), end="")
+                print(
+                    "=== Showed %d of %d injected error entries ===\n"
+                    % (max_tail_entries, total_entries),
+                    end="",
+                )
+        except OSError:
+            pass
+
+
 # This script runs and kills db_stress multiple times. It checks consistency
 # in case of unsafe crashes in RocksDB.
 def blackbox_crash_main(args, unknown_args):
@@ -1476,7 +1530,9 @@ def blackbox_crash_main(args, unknown_args):
             dict(list(cmd_params.items()) + list({"db": dbname}.items())), unknown_args
         )
 
-        hit_timeout, retcode, outs, errs = execute_cmd(cmd, cmd_params["interval"])
+        hit_timeout, retcode, outs, errs, pid = execute_cmd(cmd, cmd_params["interval"])
+
+        print_and_cleanup_fault_injection_log(pid)
 
         # Reset destroy_db_initially after each run (it may have been set by
         # command line for first run only)
@@ -1502,10 +1558,12 @@ def blackbox_crash_main(args, unknown_args):
     cmd = gen_cmd(
         dict(list(cmd_params.items()) + list({"db": dbname}.items())), unknown_args
     )
-    hit_timeout, retcode, outs, errs = execute_cmd(
+    hit_timeout, retcode, outs, errs, pid = execute_cmd(
         cmd, cmd_params["verify_timeout"], True
     )
 
+    print_and_cleanup_fault_injection_log(pid)
+
     # For the final run
     print_output_and_exit_on_error(outs, errs, args.print_stderr_separately)
 
@@ -1646,7 +1704,7 @@ def whitebox_crash_main(args, unknown_args):
         # for job scheduling or execution.
         # TODO detect a hanging condition. The job might run too long as RocksDB
         # hits a hanging bug.
-        hit_timeout, retncode, stdoutdata, stderrdata = execute_cmd(
+        hit_timeout, retncode, stdoutdata, stderrdata, pid = execute_cmd(
             cmd, exit_time - time.time() + 900
         )